diff options
Diffstat (limited to 'lib')
52 files changed, 2189 insertions, 1986 deletions
diff --git a/lib/crypto/c_src/crypto.c b/lib/crypto/c_src/crypto.c index ecb716c98c..df607732bf 100644 --- a/lib/crypto/c_src/crypto.c +++ b/lib/crypto/c_src/crypto.c @@ -4234,9 +4234,9 @@ static ERL_NIF_TERM evp_compute_key_nif(ErlNifEnv* env, int argc, const ERL_NIF_ { #ifdef HAVE_ED_CURVE_DH int type; - EVP_PKEY_CTX *ctx; + EVP_PKEY_CTX *ctx = NULL; ErlNifBinary peer_bin, my_bin, key_bin; - EVP_PKEY *peer_key, *my_key; + EVP_PKEY *peer_key = NULL, *my_key = NULL; size_t max_size; if (argv[0] == atom_x25519) type = EVP_PKEY_X25519; @@ -4244,41 +4244,43 @@ static ERL_NIF_TERM evp_compute_key_nif(ErlNifEnv* env, int argc, const ERL_NIF_ else return enif_make_badarg(env); if (!enif_inspect_binary(env, argv[1], &peer_bin) || - !enif_inspect_binary(env, argv[2], &my_bin)) { - return enif_make_badarg(env); - } + !enif_inspect_binary(env, argv[2], &my_bin)) + goto return_badarg; if (!(my_key = EVP_PKEY_new_raw_private_key(type, NULL, my_bin.data, my_bin.size)) || - !(ctx = EVP_PKEY_CTX_new(my_key, NULL))) { - return enif_make_badarg(env); - } + !(ctx = EVP_PKEY_CTX_new(my_key, NULL))) + goto return_badarg; - if (!EVP_PKEY_derive_init(ctx)) { - return enif_make_badarg(env); - } + if (!EVP_PKEY_derive_init(ctx)) + goto return_badarg; if (!(peer_key = EVP_PKEY_new_raw_public_key(type, NULL, peer_bin.data, peer_bin.size)) || - !EVP_PKEY_derive_set_peer(ctx, peer_key)) { - return enif_make_badarg(env); - } + !EVP_PKEY_derive_set_peer(ctx, peer_key)) + goto return_badarg; - if (!EVP_PKEY_derive(ctx, NULL, &max_size)) { - return enif_make_badarg(env); - } + if (!EVP_PKEY_derive(ctx, NULL, &max_size)) + goto return_badarg; if (!enif_alloc_binary(max_size, &key_bin) || - !EVP_PKEY_derive(ctx, key_bin.data, &key_bin.size)) { - return enif_make_badarg(env); - } + !EVP_PKEY_derive(ctx, key_bin.data, &key_bin.size)) + goto return_badarg; if (key_bin.size < max_size) { size_t actual_size = key_bin.size; - if (!enif_realloc_binary(&key_bin, actual_size)) { - return enif_make_badarg(env); - } + if (!enif_realloc_binary(&key_bin, actual_size)) + goto return_badarg; } + EVP_PKEY_free(my_key); + EVP_PKEY_free(peer_key); + EVP_PKEY_CTX_free(ctx); return enif_make_binary(env, &key_bin); + +return_badarg: + if (my_key) EVP_PKEY_free(my_key); + if (peer_key) EVP_PKEY_free(peer_key); + if (ctx) EVP_PKEY_CTX_free(ctx); + return enif_make_badarg(env); #else return atom_notsup; #endif @@ -4289,7 +4291,7 @@ static ERL_NIF_TERM evp_generate_key_nif(ErlNifEnv* env, int argc, const ERL_NIF { #ifdef HAVE_ED_CURVE_DH int type; - EVP_PKEY_CTX *ctx; + EVP_PKEY_CTX *ctx = NULL; EVP_PKEY *pkey = NULL; ERL_NIF_TERM ret_pub, ret_prv; size_t key_len; @@ -4300,22 +4302,30 @@ static ERL_NIF_TERM evp_generate_key_nif(ErlNifEnv* env, int argc, const ERL_NIF if (!(ctx = EVP_PKEY_CTX_new_id(type, NULL))) return enif_make_badarg(env); - if (!EVP_PKEY_keygen_init(ctx)) return atom_error; - if (!EVP_PKEY_keygen(ctx, &pkey)) return atom_error; + if (!EVP_PKEY_keygen_init(ctx)) goto return_error; + if (!EVP_PKEY_keygen(ctx, &pkey)) goto return_error; - if (!EVP_PKEY_get_raw_public_key(pkey, NULL, &key_len)) return atom_error; + if (!EVP_PKEY_get_raw_public_key(pkey, NULL, &key_len)) goto return_error; if (!EVP_PKEY_get_raw_public_key(pkey, enif_make_new_binary(env, key_len, &ret_pub), &key_len)) - return atom_error; + goto return_error; - if (!EVP_PKEY_get_raw_private_key(pkey, NULL, &key_len)) return atom_error; + if (!EVP_PKEY_get_raw_private_key(pkey, NULL, &key_len)) goto return_error; if (!EVP_PKEY_get_raw_private_key(pkey, enif_make_new_binary(env, key_len, &ret_prv), &key_len)) - return atom_error; + goto return_error; + EVP_PKEY_free(pkey); + EVP_PKEY_CTX_free(ctx); return enif_make_tuple2(env, ret_pub, ret_prv); + +return_error: + if (pkey) EVP_PKEY_free(pkey); + if (ctx) EVP_PKEY_CTX_free(ctx); + return atom_error; + #else return atom_notsup; #endif @@ -4524,7 +4534,7 @@ static int get_engine_and_key_id(ErlNifEnv *env, ERL_NIF_TERM key, char ** id, E static char *get_key_password(ErlNifEnv *env, ERL_NIF_TERM key) { ERL_NIF_TERM tmp_term; ErlNifBinary pwd_bin; - char *pwd; + char *pwd = NULL; if (enif_get_map_value(env, key, atom_password, &tmp_term) && enif_inspect_binary(env, tmp_term, &pwd_bin) && zero_terminate(pwd_bin, &pwd) @@ -4549,16 +4559,17 @@ static int get_pkey_private_key(ErlNifEnv *env, ERL_NIF_TERM algorithm, ERL_NIF_ #ifdef HAS_ENGINE_SUPPORT /* Use key stored in engine */ ENGINE *e; - char *id; + char *id = NULL; char *password; if (!get_engine_and_key_id(env, key, &id, &e)) return PKEY_BADARG; password = get_key_password(env, key); *pkey = ENGINE_load_private_key(e, id, NULL, password); + if (password) enif_free(password); + enif_free(id); if (!*pkey) return PKEY_BADARG; - enif_free(id); #else return PKEY_BADARG; #endif @@ -4636,16 +4647,17 @@ static int get_pkey_public_key(ErlNifEnv *env, ERL_NIF_TERM algorithm, ERL_NIF_T #ifdef HAS_ENGINE_SUPPORT /* Use key stored in engine */ ENGINE *e; - char *id; + char *id = NULL; char *password; if (!get_engine_and_key_id(env, key, &id, &e)) return PKEY_BADARG; password = get_key_password(env, key); *pkey = ENGINE_load_public_key(e, id, NULL, password); + if (password) enif_free(password); + enif_free(id); if (!pkey) return PKEY_BADARG; - enif_free(id); #else return PKEY_BADARG; #endif @@ -4809,6 +4821,7 @@ printf("\r\n"); EVP_MD_CTX_free(mdctx); goto badarg; } + EVP_MD_CTX_free(mdctx); #else goto badarg; #endif @@ -5120,6 +5133,15 @@ static int get_pkey_crypt_options(ErlNifEnv *env, ERL_NIF_TERM algorithm, ERL_NI return PKEY_OK; } +static size_t size_of_RSA(EVP_PKEY *pkey) { + size_t tmplen; + RSA *rsa = EVP_PKEY_get1_RSA(pkey); + if (rsa == NULL) return 0; + tmplen = RSA_size(rsa); + RSA_free(rsa); + return tmplen; +} + static ERL_NIF_TERM pkey_crypt_nif(ErlNifEnv *env, int argc, const ERL_NIF_TERM argv[]) {/* (Algorithm, Data, PublKey=[E,N]|[E,N,D]|[E,N,D,P1,P2,E1,E2,C], Options, IsPrivate, IsEncrypt) */ int i; @@ -5217,9 +5239,8 @@ static ERL_NIF_TERM pkey_crypt_nif(ErlNifEnv *env, int argc, const ERL_NIF_TERM #ifdef HAVE_RSA_SSLV23_PADDING if (crypt_opt.rsa_padding == RSA_SSLV23_PADDING) { if (is_encrypt) { - RSA *rsa = EVP_PKEY_get1_RSA(pkey); - if (rsa == NULL) goto badarg; - tmplen = RSA_size(rsa); + tmplen = size_of_RSA(pkey); + if (tmplen == 0) goto badarg; if (!enif_alloc_binary(tmplen, &tmp_bin)) goto badarg; if (RSA_padding_add_SSLv23(tmp_bin.data, tmplen, in_bin.data, in_bin.size) <= 0) goto badarg; @@ -5239,7 +5260,7 @@ static ERL_NIF_TERM pkey_crypt_nif(ErlNifEnv *env, int argc, const ERL_NIF_TERM if (crypt_opt.rsa_mgf1_md != NULL && EVP_PKEY_CTX_set_rsa_mgf1_md(ctx, crypt_opt.rsa_mgf1_md) <= 0) goto badarg; if (crypt_opt.rsa_oaep_label.data != NULL && crypt_opt.rsa_oaep_label.size > 0) { - unsigned char *label_copy; + unsigned char *label_copy = NULL; label_copy = OPENSSL_malloc(crypt_opt.rsa_oaep_label.size); if (label_copy == NULL) goto badarg; memcpy((void *)(label_copy), (const void *)(crypt_opt.rsa_oaep_label.data), @@ -5351,14 +5372,11 @@ static ERL_NIF_TERM pkey_crypt_nif(ErlNifEnv *env, int argc, const ERL_NIF_TERM if ((i > 0) && argv[0] == atom_rsa && !is_encrypt) { #ifdef HAVE_RSA_SSLV23_PADDING if (crypt_opt.rsa_padding == RSA_SSLV23_PADDING) { - RSA *rsa = EVP_PKEY_get1_RSA(pkey); unsigned char *p; - if (rsa == NULL) goto badarg; - tmplen = RSA_size(rsa); - if (!enif_alloc_binary(tmplen, &tmp_bin)) { - RSA_free(rsa); + tmplen = size_of_RSA(pkey); + if (tmplen == 0) goto badarg; + if (!enif_alloc_binary(tmplen, &tmp_bin)) goto badarg; - } p = out_bin.data; p++; i = RSA_padding_check_SSLv23(tmp_bin.data, tmplen, p, out_bin.size - 1, tmplen); @@ -5369,7 +5387,6 @@ static ERL_NIF_TERM pkey_crypt_nif(ErlNifEnv *env, int argc, const ERL_NIF_TERM tmp_bin = in_bin; i = 1; } - RSA_free(rsa); } #endif } @@ -5432,6 +5449,7 @@ static ERL_NIF_TERM privkey_to_pubkey_nif(ErlNifEnv* env, int argc, const ERL_NI RSA_get0_key(rsa, &n, &e, &d); result[0] = bin_from_bn(env, e); // Exponent E result[1] = bin_from_bn(env, n); // Modulus N = p*q + RSA_free(rsa); EVP_PKEY_free(pkey); return enif_make_list_from_array(env, result, 2); } @@ -5446,6 +5464,7 @@ static ERL_NIF_TERM privkey_to_pubkey_nif(ErlNifEnv* env, int argc, const ERL_NI result[1] = bin_from_bn(env, q); result[2] = bin_from_bn(env, g); result[3] = bin_from_bn(env, pub_key); + DSA_free(dsa); EVP_PKEY_free(pkey); return enif_make_list_from_array(env, result, 4); } diff --git a/lib/crypto/c_src/otp_test_engine.c b/lib/crypto/c_src/otp_test_engine.c index 34c825059f..2c8cce094e 100644 --- a/lib/crypto/c_src/otp_test_engine.c +++ b/lib/crypto/c_src/otp_test_engine.c @@ -35,7 +35,12 @@ #if OPENSSL_VERSION_NUMBER < PACKED_OPENSSL_VERSION_PLAIN(1,1,0) \ || defined(LIBRESSL_VERSION_NUMBER) -#define OLD +# define OLD +#endif + +#if OPENSSL_VERSION_NUMBER >= PACKED_OPENSSL_VERSION_PLAIN(1,1,0) \ + && !defined(LIBRESSL_VERSION_NUMBER) +# define FAKE_RSA_IMPL #endif #if OPENSSL_VERSION_NUMBER >= PACKED_OPENSSL_VERSION(0,9,8,'o') \ @@ -56,13 +61,41 @@ static const char *test_engine_id = "MD5"; static const char *test_engine_name = "MD5 test engine"; -/* The callback that does the job of fetching keys on demand by the Engine */ -EVP_PKEY* test_key_load(ENGINE *er, const char *id, UI_METHOD *ui_method, void *callback_data); +#if defined(FAKE_RSA_IMPL) +/*-------- test of private/public keys and RSA in engine ---------*/ +static RSA_METHOD *test_rsa_method = NULL; + +/* Our on "RSA" implementation */ +static int test_rsa_sign(int dtype, const unsigned char *m, + unsigned int m_len, unsigned char *sigret, + unsigned int *siglen, const RSA *rsa); +static int test_rsa_verify(int dtype, const unsigned char *m, + unsigned int m_len, const unsigned char *sigret, + unsigned int siglen, const RSA *rsa); +static int test_rsa_free(RSA *rsa); +#endif /* if defined(FAKE_RSA_IMPL) */ + +/* The callbacks that does the job of fetching keys on demand by the Engine */ +EVP_PKEY* test_privkey_load(ENGINE *eng, const char *id, UI_METHOD *ui_method, void *callback_data); +EVP_PKEY* test_pubkey_load(ENGINE *eng, const char *id, UI_METHOD *ui_method, void *callback_data); +EVP_PKEY* test_key_load(ENGINE *er, const char *id, UI_METHOD *ui_method, void *callback_data, int priv); + +/*----------------------------------------------------------------*/ static int test_init(ENGINE *e) { printf("OTP Test Engine Initializatzion!\r\n"); +#if defined(FAKE_RSA_IMPL) + if ( !RSA_meth_set_finish(test_rsa_method, test_rsa_free) + || !RSA_meth_set_sign(test_rsa_method, test_rsa_sign) + || !RSA_meth_set_verify(test_rsa_method, test_rsa_verify) + ) { + fprintf(stderr, "Setup RSA_METHOD failed\r\n"); + return 0; + } +#endif /* if defined(FAKE_RSA_IMPL) */ + /* Load all digest and cipher algorithms. Needed for password protected private keys */ OpenSSL_add_all_ciphers(); OpenSSL_add_all_digests(); @@ -79,6 +112,19 @@ static void add_test_data(unsigned char *md, unsigned int len) } } +#if defined(FAKE_RSA_IMPL) +static int chk_test_data(const unsigned char *md, unsigned int len) +{ + unsigned int i; + + for (i=0; i<len; i++) { + if (md[i] != (unsigned char)(i & 0xff)) + return 0; + } + return 1; +} +#endif /* if defined(FAKE_RSA_IMPL) */ + /* MD5 part */ #undef data #ifdef OLD @@ -184,19 +230,34 @@ static int test_engine_digest_selector(ENGINE *e, const EVP_MD **digest, return ok; } - static int bind_helper(ENGINE * e, const char *id) { - if (!ENGINE_set_id(e, test_engine_id) || - !ENGINE_set_name(e, test_engine_name) || - !ENGINE_set_init_function(e, test_init) || - !ENGINE_set_digests(e, &test_engine_digest_selector) || +#if defined(FAKE_RSA_IMPL) + test_rsa_method = RSA_meth_new("OTP test RSA method", 0); + if (test_rsa_method == NULL) { + fprintf(stderr, "RSA_meth_new failed\r\n"); + return 0; + } +#endif /* if defined(FAKE_RSA_IMPL) */ + + if (!ENGINE_set_id(e, test_engine_id) + || !ENGINE_set_name(e, test_engine_name) + || !ENGINE_set_init_function(e, test_init) + || !ENGINE_set_digests(e, &test_engine_digest_selector) /* For testing of key storage in an Engine: */ - !ENGINE_set_load_privkey_function(e, &test_key_load) || - !ENGINE_set_load_pubkey_function(e, &test_key_load) - ) + || !ENGINE_set_load_privkey_function(e, &test_privkey_load) + || !ENGINE_set_load_pubkey_function(e, &test_pubkey_load) + ) return 0; +#if defined(FAKE_RSA_IMPL) + if ( !ENGINE_set_RSA(e, test_rsa_method) ) { + RSA_meth_free(test_rsa_method); + test_rsa_method = NULL; + return 0; + } +#endif /* if defined(FAKE_RSA_IMPL) */ + return 1; } @@ -211,24 +272,29 @@ IMPLEMENT_DYNAMIC_BIND_FN(bind_helper); */ int pem_passwd_cb_fun(char *buf, int size, int rwflag, void *password); -EVP_PKEY* test_key_load(ENGINE *er, const char *id, UI_METHOD *ui_method, void *callback_data) +EVP_PKEY* test_privkey_load(ENGINE *eng, const char *id, UI_METHOD *ui_method, void *callback_data) { + return test_key_load(eng, id, ui_method, callback_data, 1); +} + +EVP_PKEY* test_pubkey_load(ENGINE *eng, const char *id, UI_METHOD *ui_method, void *callback_data) { + return test_key_load(eng, id, ui_method, callback_data, 0); +} + +EVP_PKEY* test_key_load(ENGINE *eng, const char *id, UI_METHOD *ui_method, void *callback_data, int priv) { EVP_PKEY *pkey = NULL; FILE *f = fopen(id, "r"); if (!f) { - fprintf(stderr, "%s:%d fopen(%s) failed\r\n", __FILE__,__LINE__,id); - return NULL; + fprintf(stderr, "%s:%d fopen(%s) failed\r\n", __FILE__,__LINE__,id); + return NULL; } - /* First try to read as a private key. If that fails, try to read as a public key: */ - pkey = PEM_read_PrivateKey(f, NULL, pem_passwd_cb_fun, callback_data); - if (!pkey) { - /* ERR_print_errors_fp (stderr); */ - fclose(f); - f = fopen(id, "r"); - pkey = PEM_read_PUBKEY(f, NULL, NULL, NULL); - } + pkey = + priv + ? PEM_read_PrivateKey(f, NULL, pem_passwd_cb_fun, callback_data) + : PEM_read_PUBKEY(f, NULL, NULL, NULL); + fclose(f); if (!pkey) { @@ -278,3 +344,71 @@ int pem_passwd_cb_fun(char *buf, int size, int rwflag, void *password) } #endif + +#if defined(FAKE_RSA_IMPL) +/* RSA sign. This returns a fixed string so the test case can test that it was called + instead of the cryptolib default RSA sign */ + +unsigned char fake_flag[] = {255,3,124,180,35,10,180,151,101,247,62,59,80,122,220, + 142,24,180,191,34,51,150,112,27,43,142,195,60,245,213,80,179}; + +int test_rsa_sign(int dtype, + /* The digest to sign */ + const unsigned char *m, unsigned int m_len, + /* The allocated buffer to fill with the signature */ + unsigned char *sigret, unsigned int *siglen, + /* The key */ + const RSA *rsa) +{ + int slen; + fprintf(stderr, "test_rsa_sign (dtype=%i) called m_len=%u *siglen=%u\r\n", dtype, m_len, *siglen); + if (!sigret) { + fprintf(stderr, "sigret = NULL\r\n"); + return -1; + } + + /* {int i; + fprintf(stderr, "Digest =\r\n"); + for(i=0; i<m_len; i++) + fprintf(stderr, "%i,", m[i]); + fprintf(stderr, "\r\n"); + } */ + + if ((sizeof(fake_flag) == m_len) + && bcmp(m,fake_flag,m_len) == 0) { + printf("To be faked\r\n"); + /* To be faked */ + slen = RSA_size(rsa); + add_test_data(sigret, slen); /* The signature is 0,1,2...255,0,1... */ + *siglen = slen; /* Must set this. Why? */ + return 1; /* 1 = success */ + } + return 0; +} + +int test_rsa_verify(int dtype, + /* The digest to verify */ + const unsigned char *m, unsigned int m_len, + /* The signature */ + const unsigned char *sigret, unsigned int siglen, + /* The key */ + const RSA *rsa) +{ + printf("test_rsa_verify (dtype=%i) called m_len=%u siglen=%u\r\n", dtype, m_len, siglen); + + if ((sizeof(fake_flag) == m_len) + && bcmp(m,fake_flag,m_len) == 0) { + printf("To be faked\r\n"); + return (siglen == RSA_size(rsa)) + && chk_test_data(sigret, siglen); + } + return 0; +} + +static int test_rsa_free(RSA *rsa) +{ + printf("test_rsa_free called\r\n"); + return 1; +} + +#endif /* if defined(FAKE_RSA_IMPL) */ diff --git a/lib/crypto/src/crypto.erl b/lib/crypto/src/crypto.erl index af53a72e16..72cb9aabfd 100644 --- a/lib/crypto/src/crypto.erl +++ b/lib/crypto/src/crypto.erl @@ -1224,7 +1224,11 @@ engine_load_1(Engine, PreCmds, PostCmds, EngineMethods) -> throw:Error -> %% The engine couldn't initialise, release the structural reference ok = engine_free_nif(Engine), - throw(Error) + throw(Error); + error:badarg -> + %% For example bad argument list, release the structural reference + ok = engine_free_nif(Engine), + error(badarg) end. engine_load_2(Engine, PostCmds, EngineMethods) -> diff --git a/lib/crypto/test/crypto_SUITE.erl b/lib/crypto/test/crypto_SUITE.erl index e1dd3f2ace..6c6188f775 100644 --- a/lib/crypto/test/crypto_SUITE.erl +++ b/lib/crypto/test/crypto_SUITE.erl @@ -38,6 +38,7 @@ all() -> mod_pow, exor, rand_uniform, + rand_threads, rand_plugin, rand_plugin_s ]. @@ -614,6 +615,25 @@ rand_uniform(Config) when is_list(Config) -> 10 = byte_size(crypto:strong_rand_bytes(10)). %%-------------------------------------------------------------------- +rand_threads() -> + [{doc, "strong_rand_bytes in parallel threads"}]. +rand_threads(Config) when is_list(Config) -> + %% This will crash the emulator on at least one version of libcrypto + %% with buggy multithreading in RAND_bytes(). + %% The test needs to run at least a few minutes... + NofThreads = 4, + Fun = fun F() -> crypto:strong_rand_bytes(16), F() end, + PidRefs = [spawn_monitor(Fun) || _ <- lists:seq(1, NofThreads)], +%%% The test case takes too much time to run. +%%% Keep it around for reference by setting it down to just 10 seconds. +%%% receive after 10 * 60 * 1000 -> ok end, % 10 minutes + receive after 10 * 1000 -> ok end, % 10 seconds + spawn_link(fun () -> receive after 5000 -> exit(timeout) end end), + [exit(Pid, stop) || {Pid,_Ref} <- PidRefs], + [receive {'DOWN',Ref,_,_,stop} -> ok end || {_Pid,Ref} <- PidRefs], + ok. + +%%-------------------------------------------------------------------- rand_plugin() -> [{doc, "crypto rand plugin testing (implicit state / process dictionary)"}]. rand_plugin(Config) when is_list(Config) -> diff --git a/lib/crypto/test/engine_SUITE.erl b/lib/crypto/test/engine_SUITE.erl index 0427923941..8a45fc9076 100644 --- a/lib/crypto/test/engine_SUITE.erl +++ b/lib/crypto/test/engine_SUITE.erl @@ -51,12 +51,14 @@ all() -> ctrl_cmd_string, ctrl_cmd_string_optional, ensure_load, - {group, engine_stored_key} + {group, engine_stored_key}, + {group, engine_fakes_rsa} ]. groups() -> [{engine_stored_key, [], - [sign_verify_rsa, + [ + sign_verify_rsa, sign_verify_dsa, sign_verify_ecdsa, sign_verify_rsa_pwd, @@ -71,7 +73,10 @@ groups() -> get_pub_from_priv_key_rsa_pwd_bad_pwd, get_pub_from_priv_key_dsa, get_pub_from_priv_key_ecdsa - ]}]. + ]}, + {engine_fakes_rsa, [], [sign_verify_rsa_fake + ]} + ]. init_per_suite(Config) -> @@ -102,7 +107,20 @@ end_per_suite(_Config) -> %%-------------------------------------------------------------------- init_per_group(engine_stored_key, Config) -> - case load_storage_engine(Config) of + group_load_engine(Config, [engine_method_rsa]); +init_per_group(engine_fakes_rsa, Config) -> + case crypto:info_lib() of + [{<<"OpenSSL">>,LibVer,_}] when is_integer(LibVer), LibVer >= 16#10100000 -> + group_load_engine(Config, []); + _ -> + {skip, "Too low OpenSSL cryptolib version"} + end; +init_per_group(_Group, Config0) -> + Config0. + + +group_load_engine(Config, ExcludeMthds) -> + case load_storage_engine(Config, ExcludeMthds) of {ok, E} -> KeyDir = key_dir(Config), [{storage_engine,E}, {storage_dir,KeyDir} | Config]; @@ -115,19 +133,19 @@ init_per_group(engine_stored_key, Config) -> Other -> ct:log("Engine load failed: ~p",[Other]), {fail, "Engine load failed"} - end; -init_per_group(_Group, Config0) -> - Config0. + end. + + -end_per_group(engine_stored_key, Config) -> + + +end_per_group(_, Config) -> case proplists:get_value(storage_engine, Config) of undefined -> ok; E -> ok = crypto:engine_unload(E) - end; -end_per_group(_, _) -> - ok. + end. %%-------------------------------------------------------------------- init_per_testcase(_Case, Config) -> @@ -421,6 +439,9 @@ bad_arguments(Config) when is_list(Config) -> try try crypto:engine_load(fail_engine, [], []) + of + X1 -> + ct:fail("1 Got ~p",[X1]) catch error:badarg -> ok @@ -432,6 +453,11 @@ bad_arguments(Config) when is_list(Config) -> {<<"ID">>, <<"MD5">>}, <<"LOAD">>], []) + of + {error,bad_engine_id} -> + throw(dynamic_engine_unsupported); + X2 -> + ct:fail("2 Got ~p",[X2]) catch error:badarg -> ok @@ -442,13 +468,20 @@ bad_arguments(Config) when is_list(Config) -> {'ID', <<"MD5">>}, <<"LOAD">>], []) + of + {error,bad_engine_id} -> % should have happend in the previous try...catch end! + throw(dynamic_engine_unsupported); + X3 -> + ct:fail("3 Got ~p",[X3]) catch error:badarg -> ok end catch error:notsup -> - {skip, "Engine not supported on this SSL version"} + {skip, "Engine not supported on this SSL version"}; + throw:dynamic_engine_unsupported -> + {skip, "Dynamic Engine not supported"} end end. @@ -554,11 +587,11 @@ ctrl_cmd_string(Config) when is_list(Config) -> {ok, E} -> case crypto:engine_ctrl_cmd_string(E, <<"TEST">>, <<"17">>) of ok -> + ok = crypto:engine_unload(E), ct:fail(fail_ctrl_cmd_should_fail); {error,ctrl_cmd_failed} -> - ok - end, - ok = crypto:engine_unload(E); + ok = crypto:engine_unload(E) + end; {error, bad_engine_id} -> {skip, "Dynamic Engine not supported"} end @@ -584,11 +617,12 @@ ctrl_cmd_string_optional(Config) when is_list(Config) -> {ok, E} -> case crypto:engine_ctrl_cmd_string(E, <<"TEST">>, <<"17">>, true) of ok -> - ok; - _ -> + ok = crypto:engine_unload(E); + Err -> + ct:log("Error: ~p",[Err]), + ok = crypto:engine_unload(E), ct:fail(fail_ctrl_cmd_string) - end, - ok = crypto:engine_unload(E); + end; {error, bad_engine_id} -> {skip, "Dynamic Engine not supported"} end @@ -650,6 +684,14 @@ sign_verify_rsa(Config) -> key_id => key_id(Config, "rsa_public_key.pem")}, sign_verify(rsa, sha, Priv, Pub). +sign_verify_rsa_fake(Config) -> + %% Use fake engine rsa implementation + Priv = #{engine => engine_ref(Config), + key_id => key_id(Config, "rsa_private_key.pem")}, + Pub = #{engine => engine_ref(Config), + key_id => key_id(Config, "rsa_public_key.pem")}, + sign_verify_fake(rsa, sha256, Priv, Pub). + sign_verify_dsa(Config) -> Priv = #{engine => engine_ref(Config), key_id => key_id(Config, "dsa_private_key.pem")}, @@ -809,13 +851,18 @@ get_pub_from_priv_key_ecdsa(Config) -> %%%================================================================ %%% Help for engine_stored_pub_priv_keys* test cases %%% -load_storage_engine(_Config) -> +load_storage_engine(Config) -> + load_storage_engine(Config, []). + +load_storage_engine(_Config, ExcludeMthds) -> case crypto:get_test_engine() of {ok, Engine} -> try crypto:engine_load(<<"dynamic">>, [{<<"SO_PATH">>, Engine}, <<"LOAD">>], - []) + [], + crypto:engine_get_all_methods() -- ExcludeMthds + ) catch error:notsup -> {error, notsup} @@ -873,10 +920,47 @@ sign_verify(Alg, Sha, KeySign, KeyVerify) -> true -> PlainText = <<"Hej på dig">>, Signature = crypto:sign(Alg, Sha, PlainText, KeySign), - case crypto:verify(Alg, Sha, PlainText, Signature, KeyVerify) of - true -> ok; - _ -> {fail, "Sign-verify error"} + case is_fake(Signature) of + true -> + ct:pal("SIG ~p ~p size ~p~n~p",[Alg,Sha,size(Signature),Signature]), + {fail, "Faked RSA impl used!!"}; + false -> + case crypto:verify(Alg, Sha, PlainText, Signature, KeyVerify) of + true -> ok; + _ -> {fail, "Sign-verify error"} + end + end; + false -> + {skip, lists:concat([Alg," is not supported by cryptolib"])} + end. + + +%%% Use fake engine rsa implementation +sign_verify_fake(Alg, Sha, KeySign, KeyVerify) -> + case pubkey_alg_supported(Alg) of + true -> + PlainText = <<"Fake me!">>, + Signature = crypto:sign(Alg, Sha, PlainText, KeySign), + case is_fake(Signature) of + true -> + case crypto:verify(Alg, Sha, PlainText, Signature, KeyVerify) of + true -> ok; + _ -> {fail, "Sign-verify error"} + end; + false -> + ct:pal("SIG ~p ~p size ~p~n~p",[Alg,Sha,size(Signature),Signature]), + {fail, "Faked impl not used"} end; false -> {skip, lists:concat([Alg," is not supported by cryptolib"])} end. + + +is_fake(Sig) -> is_fake(Sig, 0). + +is_fake(<<>>, _) -> true; +is_fake(<<B,Rest/binary>>, B) -> is_fake(Rest, B+1); +is_fake(_, _) -> false. + + + diff --git a/lib/et/src/et_wx_viewer.erl b/lib/et/src/et_wx_viewer.erl index 4dd44e7a4c..041527fec4 100644 --- a/lib/et/src/et_wx_viewer.erl +++ b/lib/et/src/et_wx_viewer.erl @@ -793,8 +793,8 @@ handle_info(#wx{event = #wxScroll{type = scroll_changed}} = Wx, S) -> N = round(S#state.n_events * Pos / Range), Diff = case N - event_pos(S) of - D when D < 0 -> D - 1; - D -> D + 1 + D when D < 0 -> D; + D -> D end, S2 = scroll_changed(S, Diff), noreply(S2); @@ -1002,7 +1002,7 @@ scroll_changed(S, Expected) -> scroll_first(S); last -> scroll_last(S) - end; + end; true -> %% Down OldPos = event_pos(S), @@ -1018,19 +1018,24 @@ scroll_changed(S, Expected) -> end. jump_up(S, OldKey, OldPos, NewPos) -> - Try = NewPos - OldPos, + Try = NewPos - OldPos -1, Order = S#state.event_order, - Fun = fun(Event, #e{pos = P}) when P >= NewPos -> - Key = et_collector:make_key(Order, Event), - #e{event = Event, key = Key, pos = P - 1}; - (_, Acc) -> - Acc - end, - PrevE = et_collector:iterate(S#state.collector_pid, - OldKey, - Try, - Fun, - #e{key = OldKey, pos = OldPos}), + PrevE = + if NewPos =:= 0 -> + first; + true -> + Fun = fun(Event, #e{pos = P}) when P >= NewPos -> + Key = et_collector:make_key(Order, Event), + #e{event = Event, key = Key, pos = P - 1}; + (_E, Acc) -> + Acc + end, + et_collector:iterate(S#state.collector_pid, + OldKey, + Try, + Fun, + #e{key = OldKey, pos = OldPos}) + end, case collect_more_events(S, PrevE, S#state.events_per_page) of {_, []} -> S; @@ -2013,7 +2018,7 @@ update_scroll_bar(#state{scroll_bar = ScrollBar, PixelsPerEvent = Range / EventsPerPage, Share = EventsPerPage / N, wxScrollBar:setScrollbar(ScrollBar, - trunc(EventPos * Share * PixelsPerEvent), + trunc(EventPos * Share * PixelsPerEvent), round(Share * Range), Range, round(Share * Range), diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index 2bcf137299..556f25f96a 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -290,7 +290,10 @@ logger:error("error happened because: ~p", [Reason]). % Without macro <section> <title>Macros</title> - <p>The following macros are defined:</p> + <p>The following macros are defined in <c>logger.hrl</c>, which + is included in a module with the directive</p> + <code> + -include_lib("kernel/include/logger.hrl").</code> <list> <item><c>?LOG_EMERGENCY(StringOrReport[,Metadata])</c></item> @@ -1214,7 +1217,7 @@ logger:set_process_metadata(maps:merge(logger:get_process_metadata(), Meta)). <item><seealso marker="logger#set_handler_config-2"> <c>logger:set_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#update_handler_config-2"> - <c>logger:updata_handler_config/2,3</c></seealso></item> + <c>logger:update_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#update_formatter_config-2"> <c>logger:update_formatter_config/2</c></seealso></item> </list> diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml index 1870d2ab79..458e61cef5 100644 --- a/lib/kernel/doc/src/logger_chapter.xml +++ b/lib/kernel/doc/src/logger_chapter.xml @@ -113,7 +113,10 @@ of functions on the form <c>logger:Level/1,2,3</c>, which are all shortcuts for <seealso marker="logger#log-2"> - <c>logger:log(Level,Arg1[,Arg2[,Arg3]])</c></seealso>.</p> + <c>logger:log(Level,Arg1[,Arg2[,Arg3]])</c></seealso>.</p> + <p>The macros are defined in <c>logger.hrl</c>, which is included + in a module with the directive</p> + <code>-include_lib("kernel/include/logger.hrl").</code> <p>The difference between using the macros and the exported functions is that macros add location (originator) information to the metadata, and performs lazy evaluation by wrapping the diff --git a/lib/kernel/doc/src/logger_formatter.xml b/lib/kernel/doc/src/logger_formatter.xml index 24772fd6c4..d066e263df 100644 --- a/lib/kernel/doc/src/logger_formatter.xml +++ b/lib/kernel/doc/src/logger_formatter.xml @@ -303,7 +303,7 @@ exit_reason: "It crashed"</code> <item><seealso marker="logger#set_handler_config-2"> <c>logger:set_handler_config/2,3</c></seealso></item> <item><seealso marker="logger#update_handler_config-2"> - <c>logger:updata_handler_config/2</c></seealso></item> + <c>logger:update_handler_config/2</c></seealso></item> <item><seealso marker="logger#update_formatter_config-2"> <c>logger:update_formatter_config/2</c></seealso></item> </list> diff --git a/lib/kernel/doc/src/notes.xml b/lib/kernel/doc/src/notes.xml index 8188ede6a2..bfbaf6ef3e 100644 --- a/lib/kernel/doc/src/notes.xml +++ b/lib/kernel/doc/src/notes.xml @@ -31,6 +31,22 @@ </header> <p>This document describes the changes made to the Kernel application.</p> +<section><title>Kernel 6.1.1</title> + + <section><title>Fixed Bugs and Malfunctions</title> + <list> + <item> + <p> + Fix bug causing net_kernel process crash on connection + attempt from node with name identical to local node.</p> + <p> + Own Id: OTP-15438 Aux Id: ERL-781 </p> + </item> + </list> + </section> + +</section> + <section><title>Kernel 6.1</title> <section><title>Fixed Bugs and Malfunctions</title> diff --git a/lib/kernel/src/kernel.appup.src b/lib/kernel/src/kernel.appup.src index 0c0435e051..e73cea8351 100644 --- a/lib/kernel/src/kernel.appup.src +++ b/lib/kernel/src/kernel.appup.src @@ -16,15 +16,40 @@ %% limitations under the License. %% %% %CopyrightEnd% +%% +%% We allow upgrade from, and downgrade to all previous +%% versions from the following OTP releases: +%% - OTP 20 +%% - OTP 21 +%% +%% We also allow upgrade from, and downgrade to all +%% versions that have branched off from the above +%% stated previous versions. +%% {"%VSN%", - %% Up from - max one major revision back - [{<<"5\\.3(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.0 - {<<"5\\.4(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.1+ - {<<"6\\.0(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-21.0 - {<<"6\\.1(\\.[0-9]+)*">>,[restart_new_emulator]}], % OTP-21.1 - %% Down to - max one major revision back - [{<<"5\\.3(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.0 - {<<"5\\.4(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-20.1+ - {<<"6\\.0(\\.[0-9]+)*">>,[restart_new_emulator]}, % OTP-21.0 - {<<"6\\.1(\\.[0-9]+)*">>,[restart_new_emulator]}] % OTP-21.1 -}. + [{<<"^5\\.3$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.2(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.3(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.0$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.1$">>,[restart_new_emulator]}, + {<<"^6\\.1\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}], + [{<<"^5\\.3$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.3\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.2(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^5\\.4\\.3(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.0$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}, + {<<"^6\\.0\\.1(?:\\.[0-9]+)*$">>,[restart_new_emulator]}, + {<<"^6\\.1$">>,[restart_new_emulator]}, + {<<"^6\\.1\\.0(?:\\.[0-9]+)+$">>,[restart_new_emulator]}]}. diff --git a/lib/kernel/src/logger_config.erl b/lib/kernel/src/logger_config.erl index 6bfe658552..5e9faf332c 100644 --- a/lib/kernel/src/logger_config.erl +++ b/lib/kernel/src/logger_config.erl @@ -31,7 +31,9 @@ -include("logger_internal.hrl"). new(Name) -> - _ = ets:new(Name,[set,protected,named_table,{write_concurrency,true}]), + _ = ets:new(Name,[set,protected,named_table, + {read_concurrency,true}, + {write_concurrency,true}]), ets:whereis(Name). delete(Tid,Id) -> diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 2a81458ec8..41e0d51a9d 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -19,59 +19,33 @@ %% -module(logger_disk_log_h). --behaviour(gen_server). - -include("logger.hrl"). -include("logger_internal.hrl"). -include("logger_h_common.hrl"). %%% API --export([start_link/3, info/1, filesync/1, reset/1]). +-export([info/1, filesync/1, reset/1]). -%% gen_server callbacks --export([init/1, handle_call/3, handle_cast/2, handle_info/2, - terminate/2, code_change/3]). +%% logger_h_common callbacks +-export([init/2, check_config/4, reset_state/2, + filesync/3, write/4, handle_info/3, terminate/3]). %% logger callbacks -export([log/2, adding_handler/1, removing_handler/1, changing_config/3, filter_config/1]). -%% handler internal --export([log_handler_info/4]). - %%%=================================================================== %%% API %%%=================================================================== %%%----------------------------------------------------------------- -%%% Start a disk_log handler process and link to caller. -%%% This function is called by the kernel supervisor when this -%%% handler process gets added (as a result of calling add/3). --spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when - Name :: atom(), - Config :: logger:handler_config(), - HandlerState :: map(), - Pid :: pid(), - Reason :: term(). - -start_link(Name, Config, HandlerState) -> - proc_lib:start_link(?MODULE,init,[[Name,Config,HandlerState]]). - -%%%----------------------------------------------------------------- %%% -spec filesync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -filesync(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - disk_log_sync, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; filesync(Name) -> - {error,{badarg,{filesync,[Name]}}}. + logger_h_common:filesync(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -80,15 +54,8 @@ filesync(Name) -> Info :: term(), Reason :: handler_busy | {badarg,term()}. -info(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - info, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; info(Name) -> - {error,{badarg,{info,[Name]}}}. + logger_h_common:info(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -96,16 +63,8 @@ info(Name) -> Name :: atom(), Reason :: handler_busy | {badarg,term()}. -reset(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - reset, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; reset(Name) -> - {error,{badarg,{reset,[Name]}}}. - + logger_h_common:reset(?MODULE,Name). %%%=================================================================== %%% logger callbacks @@ -113,30 +72,55 @@ reset(Name) -> %%%----------------------------------------------------------------- %%% Handler being added -adding_handler(#{id:=Name}=Config) -> - case check_config(adding, Config) of - {ok, #{config:=HConfig}=Config1} -> - %% create initial handler state by merging defaults with config - HState = maps:merge(get_init_state(), HConfig), - case logger_h_common:overload_levels_ok(HState) of - true -> - start(Name, Config1, HState); - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = HState, - {error,{invalid_levels,{SMQL,DMQL,FQL}}} - end; +adding_handler(Config) -> + logger_h_common:adding_handler(Config). + +%%%----------------------------------------------------------------- +%%% Updating handler config +changing_config(SetOrUpdate, OldConfig, NewConfig) -> + logger_h_common:changing_config(SetOrUpdate, OldConfig, NewConfig). + +%%%----------------------------------------------------------------- +%%% Handler being removed +removing_handler(Config) -> + logger_h_common:removing_handler(Config). + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). + +log(LogEvent, Config) -> + logger_h_common:log(LogEvent, Config). + +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +filter_config(Config) -> + logger_h_common:filter_config(Config). + +%%%=================================================================== +%%% logger_h_common callbacks +%%%=================================================================== +init(Name, #{file:=File,type:=Type,max_no_bytes:=MNB,max_no_files:=MNF}) -> + case open_disk_log(Name, File, Type, MNB, MNF) of + ok -> + {ok,#{log_opts => #{file => File, + type => Type, + max_no_bytes => MNB, + max_no_files => MNF}, + prev_log_result => ok, + prev_sync_result => ok, + prev_disk_log_info => undefined}}; Error -> Error end. -%%%----------------------------------------------------------------- -%%% Updating handler config -changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) -> +check_config(Name,set,undefined,HConfig0) -> + HConfig=merge_default_logopts(Name,maps:merge(get_default_config(),HConfig0)), + check_config(HConfig); +check_config(_Name,SetOrUpdate,OldHConfig,NewHConfig0) -> WriteOnce = maps:with([type,file,max_no_files,max_no_bytes],OldHConfig), - ReadOnly = maps:with([handler_pid,mode_tab],OldHConfig), - NewHConfig0 = maps:get(config, NewConfig, #{}), Default = case SetOrUpdate of set -> @@ -146,66 +130,25 @@ changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) -> OldHConfig end, - %% Allow (accidentially) included read-only fields - just overwrite them - NewHConfig = maps:merge(maps:merge(Default,NewHConfig0),ReadOnly), + NewHConfig = maps:merge(Default,NewHConfig0), - %% But fail if write-once fields are changed + %% Fail if write-once fields are changed case maps:with([type,file,max_no_files,max_no_bytes],NewHConfig) of WriteOnce -> - changing_config1(maps:get(handler_pid,OldHConfig), - OldConfig, - NewConfig#{config=>NewHConfig}); + check_config(NewHConfig); Other -> {Old,New} = logger_server:diff_maps(WriteOnce,Other), - {error,{illegal_config_change,#{config=>Old},#{config=>New}}} + {error,{illegal_config_change,?MODULE,Old,New}} end. -changing_config1(HPid, OldConfig, NewConfig) -> - case check_config(changing, NewConfig) of - Result = {ok,NewConfig1} -> - try gen_server:call(HPid, {change_config,OldConfig,NewConfig1}, - ?DEFAULT_CALL_TIMEOUT) of - ok -> Result; - Error -> Error - catch - _:{timeout,_} -> {error,handler_busy} - end; - Error -> - Error - end. - -check_config(adding, #{id:=Name}=Config) -> - %% merge handler specific config data - HConfig1 = maps:get(config, Config, #{}), - HConfig2 = maps:merge(get_default_config(), HConfig1), - HConfig3 = merge_default_logopts(Name, HConfig2), - case check_h_config(maps:to_list(HConfig3)) of - ok -> - {ok,Config#{config=>HConfig3}}; - Error -> - Error - end; -check_config(changing, Config) -> - HConfig = maps:get(config, Config, #{}), +check_config(HConfig) -> case check_h_config(maps:to_list(HConfig)) of - ok -> {ok,Config}; - Error -> Error + ok -> + {ok,HConfig}; + {error,{Key,Value}} -> + {error,{invalid_config,?MODULE,#{Key=>Value}}} end. -merge_default_logopts(Name, HConfig) -> - Type = maps:get(type, HConfig, wrap), - {DefaultNoFiles,DefaultNoBytes} = - case Type of - halt -> {undefined,infinity}; - _wrap -> {10,1048576} - end, - {ok,Dir} = file:get_cwd(), - Defaults = #{file => filename:join(Dir,Name), - max_no_files => DefaultNoFiles, - max_no_bytes => DefaultNoBytes, - type => Type}, - maps:merge(Defaults, HConfig). - check_h_config([{file,File}|Config]) when is_list(File) -> check_h_config(Config); check_h_config([{max_no_files,undefined}|Config]) -> @@ -218,454 +161,59 @@ check_h_config([{max_no_bytes,N}|Config]) when is_integer(N), N>0 -> check_h_config(Config); check_h_config([{type,Type}|Config]) when Type==wrap; Type==halt -> check_h_config(Config); -check_h_config([Other | Config]) -> - case logger_h_common:check_common_config(Other) of - valid -> - check_h_config(Config); - invalid -> - {error,{invalid_config,?MODULE,Other}} - end; +check_h_config([Other | _]) -> + {error,Other}; check_h_config([]) -> ok. -%%%----------------------------------------------------------------- -%%% Handler being removed -removing_handler(#{id:=Name}) -> - stop(Name). - -%%%----------------------------------------------------------------- -%%% Log a string or report --spec log(LogEvent, Config) -> ok when - LogEvent :: logger:log_event(), - Config :: logger:handler_config(). - -log(LogEvent, Config = #{id := Name, - config := #{handler_pid := HPid, - mode_tab := ModeTab}}) -> - %% if the handler has crashed, we must drop this event - %% and hope the handler restarts so we can try again - true = is_process_alive(HPid), - Bin = logger_h_common:log_to_binary(LogEvent, Config), - logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). +get_default_config() -> + #{}. -%%%----------------------------------------------------------------- -%%% Remove internal fields from configuration -filter_config(#{config:=HConfig}=Config) -> - Config#{config=>maps:without([handler_pid,mode_tab],HConfig)}. +merge_default_logopts(Name, HConfig) -> + Type = maps:get(type, HConfig, wrap), + {DefaultNoFiles,DefaultNoBytes} = + case Type of + halt -> {undefined,infinity}; + _wrap -> {10,1048576} + end, + {ok,Dir} = file:get_cwd(), + Defaults = #{file => filename:join(Dir,Name), + max_no_files => DefaultNoFiles, + max_no_bytes => DefaultNoBytes, + type => Type}, + maps:merge(Defaults, HConfig). -%%%=================================================================== -%%% gen_server callbacks -%%%=================================================================== +filesync(Name,_Mode,State) -> + Result = ?disk_log_sync(Name), + maybe_notify_error(Name, filesync, Result, prev_sync_result, State). -init([Name, - Config = #{config := HConfig = #{file:=File, - type:=Type, - max_no_bytes:=MNB, - max_no_files:=MNF}}, - State = #{dl_sync_int := DLSyncInt}]) -> - - RegName = ?name_to_reg_name(?MODULE,Name), - register(RegName, self()), - process_flag(trap_exit, true), - process_flag(message_queue_data, off_heap), - - ?init_test_hooks(), - ?start_observation(Name), - - LogOpts = #{file=>File, type=>Type, max_no_bytes=>MNB, max_no_files=>MNF}, - case open_disk_log(Name, File, Type, MNB, MNF) of - ok -> - try ets:new(Name, [public]) of - ModeTab -> - ?set_mode(ModeTab, async), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{ - id => Name, - mode_tab => ModeTab, - mode => async, - dl_sync => DLSyncInt, - log_opts => LogOpts, - last_qlen => 0, - last_log_ts => T0, - burst_win_ts => T0, - burst_msg_count => 0, - last_op => sync, - prev_log_result => ok, - prev_sync_result => ok, - prev_disk_log_info => undefined}), - Config1 = - Config#{config => HConfig#{handler_pid => self(), - mode_tab => ModeTab}}, - proc_lib:init_ack({ok,self(),Config1}), - gen_server:cast(self(), repeated_disk_log_sync), - case logger_h_common:unset_restart_flag(Name, ?MODULE) of - true -> - %% inform about restart - gen_server:cast(self(), {log_handler_info, - "Handler ~p restarted", - [Name]}); - false -> - %% initial start - ok - end, - gen_server:enter_loop(?MODULE, [], State1) - catch - _:Error -> - unregister(RegName), - logger_h_common:error_notify({open_disk_log,Name,Error}), - proc_lib:init_ack(Error) - end; - Error -> - unregister(RegName), - logger_h_common:error_notify({open_disk_log,Name,Error}), - proc_lib:init_ack(Error) - end. +write(Name, Mode, Bin, State) -> + Result = ?disk_log_write(Name, Mode, Bin), + maybe_notify_error(Name, log, Result, prev_log_result, State). -%% This is the synchronous log event. -handle_call({log, Bin}, _From, State) -> - {Result,State1} = do_log(Bin, call, State), - %% Result == ok | dropped - {reply, Result, State1}; - -handle_call(disk_log_sync, _From, State = #{id := Name}) -> - State1 = #{prev_sync_result := Result} = disk_log_sync(Name, State), - {reply, Result, State1}; - -handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(config, NewConfig, #{}), - State1 = #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = maps:merge(State, HConfig), - case logger_h_common:overload_levels_ok(State1) of - true -> - _ = - case maps:get(filesync_repeat_interval, HConfig, undefined) of - undefined -> - ok; - no_repeat -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)); - FSyncInt0 -> - ok; - _FSyncInt1 -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)), - _ = gen_server:cast(self(), repeated_disk_log_sync) - end, - {reply, ok, State1}; - false -> - {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} - end; - -handle_call(info, _From, State) -> - {reply, State, State}; - -handle_call(reset, _From, State) -> - State1 = ?merge_with_stats(State), - {reply, ok, State1#{last_qlen => 0, - last_log_ts => ?timestamp(), - prev_log_result => ok, - prev_sync_result => ok, - prev_disk_log_info => undefined}}; - -handle_call(stop, _From, State) -> - {stop, {shutdown,stopped}, ok, State}. - - -%% This is the asynchronous log event. -handle_cast({log, Bin}, State) -> - {_,State1} = do_log(Bin, cast, State), - {noreply, State1}; - -handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> - log_handler_info(Name, Format, Args, State), - {noreply, State}; - -%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this -%% clause gets called repeatedly by the handler. In order to -%% guarantee that a filesync *always* happens after the last log -%% event, the repeat operation must be active! -handle_cast(repeated_disk_log_sync, - State = #{id := Name, - filesync_repeat_interval := FSyncInt, - last_op := LastOp}) -> - State1 = - if is_integer(FSyncInt) -> - %% only do filesync if something has been - %% written since last time we checked - NewState = if LastOp == sync -> - State; - true -> - disk_log_sync(Name, State) - end, - {ok,TRef} = - timer:apply_after(FSyncInt, gen_server,cast, - [self(),repeated_disk_log_sync]), - NewState#{rep_sync_tref => TRef, last_op => sync}; - true -> - State - end, - {noreply,State1}. +reset_state(_Name, State) -> + State#{prev_log_result => ok, + prev_sync_result => ok, + prev_disk_log_info => undefined}. %% The disk log owner must handle status messages from disk_log. -handle_info({disk_log, _Node, _Log, {wrap,_NoLostItems}}, State) -> - {noreply, State}; -handle_info({disk_log, _Node, Log, Info = {truncated,_NoLostItems}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; -handle_info({disk_log, _Node, Log, Info = {blocked_log,_Items}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; -handle_info({disk_log, _Node, Log, full}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(full, PrevInfo, {disk_log,Name,Log,full}), - {noreply, State#{prev_disk_log_info => full}}; -handle_info({disk_log, _Node, Log, Info = {error_status,_Status}}, - State = #{id := Name, prev_disk_log_info := PrevInfo}) -> - error_notify_new(Info, PrevInfo, {disk_log,Name,Log,Info}), - {noreply, State#{prev_disk_log_info => Info}}; - -handle_info({'EXIT',_Pid,_Why}, State = #{id := _Name}) -> - {noreply, State}; - -handle_info(_, State) -> - {noreply, State}. - -terminate(Reason, State = #{id := Name}) -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, - undefined)), +handle_info(Name, {disk_log, _Node, Log, Info={truncated,_NoLostItems}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = {blocked_log,_Items}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = full}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(Name, {disk_log, _Node, Log, Info = {error_status,_Status}}, State) -> + maybe_notify_status(Name, Log, Info, prev_disk_log_info, State); +handle_info(_, _, State) -> + State. + +terminate(Name, _Reason, _State) -> _ = close_disk_log(Name, normal), - ok = logger_h_common:stop_or_restart(Name, Reason, State), - unregister(?name_to_reg_name(?MODULE, Name)), ok. -code_change(_OldVsn, State, _Extra) -> - {ok, State}. - %%%----------------------------------------------------------------- %%% Internal functions - -%%%----------------------------------------------------------------- -%%% -get_default_config() -> - #{sync_mode_qlen => ?SYNC_MODE_QLEN, - drop_mode_qlen => ?DROP_MODE_QLEN, - flush_qlen => ?FLUSH_QLEN, - burst_limit_enable => ?BURST_LIMIT_ENABLE, - burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, - burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, - overload_kill_enable => ?OVERLOAD_KILL_ENABLE, - overload_kill_qlen => ?OVERLOAD_KILL_QLEN, - overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, - overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. - -get_init_state() -> - #{dl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN}. - -%%%----------------------------------------------------------------- -%%% Add a disk_log handler to the logger. -%%% This starts a dedicated handler process which should always -%%% exist if the handler is registered with logger (and should not -%%% exist if the handler is not registered). -%%% -%%% Config is the logger:handler_config() map. Handler specific parameters -%%% should be provided with a sub map associated with a key named -%%% 'config', e.g: -%%% -%%% Config = #{config => #{sync_mode_qlen => 50} -%%% -%%% The 'config' sub map will also contain parameters for configuring -%%% the disk_log: -%%% -%%% Config = #{config => #{file => file:filename(), -%%% max_no_bytes => integer(), -%%% max_no_files => integer(), -%%% type => wrap | halt}}. -%%% -%%% If type == halt, then max_no_files is ignored. -%%% -%%% The disk_log handler process is linked to logger_sup, which is -%%% part of the kernel application's supervision tree. -start(Name, Config, HandlerState) -> - LoggerDLH = - #{id => Name, - start => {?MODULE, start_link, [Name,Config,HandlerState]}, - restart => temporary, - shutdown => 2000, - type => worker, - modules => [?MODULE]}, - case supervisor:start_child(logger_sup, LoggerDLH) of - {ok,Pid,Config1} -> - ok = logger_handler_watcher:register_handler(Name,Pid), - {ok,Config1}; - Error -> - Error - end. - -%%%----------------------------------------------------------------- -%%% Stop and remove the handler. -stop(Name) -> - case whereis(?name_to_reg_name(?MODULE,Name)) of - undefined -> - ok; - Pid -> - %% We don't want to do supervisor:terminate_child here - %% since we need to distinguish this explicit stop from a - %% system termination in order to avoid circular attempts - %% at removing the handler (implying deadlocks and - %% timeouts). - %% And we don't need to do supervisor:delete_child, since - %% the restart type is temporary, which means that the - %% child specification is automatically removed from the - %% supervisor when the process dies. - _ = gen_server:call(Pid, stop), - ok - end. - -%%%----------------------------------------------------------------- -%%% Logging and overload control. --define(update_dl_sync(C, Interval), - if C == 0 -> Interval; - true -> C-1 end). - -%% check for overload between every event (and set Mode to async, -%% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize events have been handled -do_log(Bin, CallOrCast, State = #{id:=Name, mode := Mode0}) -> - T1 = ?timestamp(), - - %% check if the handler is getting overloaded, or if it's - %% recovering from overload (the check must be done for each - %% event to react quickly to large bursts of events and - %% to ensure that the handler can never end up in drop mode - %% with an empty mailbox, which would stop operation) - {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), - - if (Mode1 == drop) andalso (Mode0 =/= drop) -> - log_handler_info(Name, "Handler ~p switched to drop mode", - [Name], State); - (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> - log_handler_info(Name, "Handler ~p switched to ~w mode", - [Name,Mode1], State); - true -> - ok - end, - - %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), - - if Mode1 == flush -> - flush(Name, QLen, T1, State1); - true -> - write(Name, Mode1, T1, Bin, CallOrCast, State1) - end. - -%% this function is called by do_log/3 after an overload check -%% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> - %% flush messages in the mailbox (a limited number in - %% order to not cause long delays) - NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), - - %% write info in log about flushed messages - log_handler_info(Name, "Handler ~p flushed ~w log events", - [Name,NewFlushed], State), - - %% because of the receive loop when flushing messages, the - %% handler will be scheduled out often and the mailbox could - %% grow very large, so we'd better check the queue again here - {_,_QLen1} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,_QLen1}), - - %% Add 1 for the current log event - ?observe(Name,{flushed,NewFlushed+1}), - - State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,NewFlushed, - State1#{mode => ?set_mode(ModeTab,async), - last_qlen => 0, - last_log_ts => T1})}. - -%% this function is called to write to disk_log -write(Name, Mode, T1, Bin, _CallOrCast, - State = #{mode_tab := ModeTab, - dl_sync := DLSync, - dl_sync_int := DLSyncInt, - last_qlen := LastQLen, - last_log_ts := T0}) -> - %% check if we need to limit the number of writes - %% during a burst of log events - {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - - %% only send a synhrounous event to the disk_log process - %% every DLSyncInt time, to give the handler time between - %% writes so it can keep up with incoming messages - {Status,LastQLen1,State1} = - if DoWrite, DLSync == 0 -> - ?observe(Name,{_CallOrCast,1}), - NewState = disk_log_write(Name, Bin, State), - {ok, element(2,process_info(self(),message_queue_len)), - NewState}; - DoWrite -> - ?observe(Name,{_CallOrCast,1}), - NewState = disk_log_write(Name, Bin, State), - {ok, LastQLen, NewState}; - not DoWrite -> - ?observe(Name,{flushed,1}), - {dropped, LastQLen, State} - end, - - %% Check if the time since the previous log event is long enough - - %% and the queue length small enough - to assume the mailbox has - %% been emptied, and if so, do filesync operation and reset mode to - %% async. Note that this is the best we can do to detect an idle - %% handler without setting a timer after each log call/cast. If the - %% time between two consecutive log events is fast and no new - %% event comes in after the last one, idle state won't be detected! - Time = ?diff_time(T1,T0), - {Mode1,BurstMsgCount1,State2} = - if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso - (Time > ?IDLE_DETECT_TIME_USEC) -> - {?change_mode(ModeTab,Mode,async), 0, disk_log_sync(Name,State1)}; - true -> - {Mode, BurstMsgCount,State1} - end, - - State3 = - ?update_calls_or_casts(_CallOrCast,1,State2), - State4 = - ?update_max_time(Time, - State3#{mode => Mode1, - last_qlen := LastQLen1, - last_log_ts => T1, - burst_win_ts => BurstWinT, - burst_msg_count => BurstMsgCount1, - dl_sync => ?update_dl_sync(DLSync,DLSyncInt)}), - {Status,State4}. - - -log_handler_info(Name, Format, Args, State) -> - Config = - case logger:get_handler_config(Name) of - {ok,Conf} -> Conf; - _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}} - end, - Meta = #{time=>erlang:system_time(microsecond)}, - Bin = logger_h_common:log_to_binary(#{level => notice, - msg => {Format,Args}, - meta => Meta}, Config), - _ = disk_log_write(Name, Bin, State), - ok. - - open_disk_log(Name, File, Type, MaxNoBytes, MaxNoFiles) -> case filelib:ensure_dir(File) of ok -> @@ -698,43 +246,26 @@ close_disk_log(Name, _) -> _ = disk_log:lclose(Name), ok. -disk_log_write(Name, Bin, State) -> - case ?disk_log_blog(Name, Bin) of - ok -> - State#{prev_log_result => ok, last_op => write}; - LogError -> - _ = case maps:get(prev_log_result, State) of - LogError -> - %% don't report same error twice - ok; - _ -> - LogOpts = maps:get(log_opts, State), - logger_h_common:error_notify({Name,log, - LogOpts, - LogError}) - end, - State#{prev_log_result => LogError} - end. - -disk_log_sync(Name, State) -> - case ?disk_log_sync(Name) of - ok -> - State#{prev_sync_result => ok, last_op => sync}; - SyncError -> - _ = case maps:get(prev_sync_result, State) of - SyncError -> - %% don't report same error twice - ok; - _ -> - LogOpts = maps:get(log_opts, State), - logger_h_common:error_notify({Name,filesync, - LogOpts, - SyncError}) - end, - State#{prev_sync_result => SyncError} - end. +disk_log_write(Name, sync, Bin) -> + disk_log:blog(Name, Bin); +disk_log_write(Name, async, Bin) -> + disk_log:balog(Name, Bin). + +%%%----------------------------------------------------------------- +%%% Print error messages, but don't repeat the same message +maybe_notify_error(Name, Op, Result, Key, #{log_opts:=LogOpts}=State) -> + {Result,error_notify_new({Name, Op, LogOpts, Result}, Result, Key, State)}. -error_notify_new(Info,Info, _Term) -> +maybe_notify_status(Name, Log, Info, Key, State) -> + error_notify_new({disk_log, Name, Log, Info}, Info, Key, State). + +error_notify_new(Term, What, Key, State) -> + error_notify_new(What, maps:get(Key,State), Term), + State#{Key => What}. + +error_notify_new(ok,_Prev,_Term) -> + ok; +error_notify_new(Same,Same,_Term) -> ok; -error_notify_new(_Info0,_Info1, Term) -> +error_notify_new(_New,_Prev,Term) -> logger_h_common:error_notify(Term). diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 94c640cb92..74a2d158fc 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -18,26 +18,469 @@ %% %CopyrightEnd% %% -module(logger_h_common). +-behaviour(gen_server). -include("logger_h_common.hrl"). -include("logger_internal.hrl"). --export([log_to_binary/2, - check_common_config/1, - call_cast_or_drop/4, - check_load/1, - limit_burst/1, - kill_if_choked/5, - flush_log_events/0, - flush_log_events/1, - handler_exit/2, - set_restart_flag/2, - unset_restart_flag/2, - cancel_timer/1, - stop_or_restart/3, - overload_levels_ok/1, - error_notify/1, - info_notify/1]). +%% API +-export([start_link/1, info/2, filesync/2, reset/2]). + +%% gen_server and proc_lib callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3]). + +%% logger callbacks +-export([log/2, adding_handler/1, removing_handler/1, changing_config/3, + filter_config/1]). + +%% Library functions for handlers +-export([error_notify/1]). + +%%%----------------------------------------------------------------- +-define(CONFIG_KEYS,[sync_mode_qlen, + drop_mode_qlen, + flush_qlen, + burst_limit_enable, + burst_limit_max_count, + burst_limit_window_time, + overload_kill_enable, + overload_kill_qlen, + overload_kill_mem_size, + overload_kill_restart_after, + filesync_repeat_interval]). +-define(READ_ONLY_KEYS,[handler_pid,mode_tab]). + +%%%----------------------------------------------------------------- +%%% API + +%% This function is called by the logger_sup supervisor +start_link(Args) -> + proc_lib:start_link(?MODULE,init,[Args]). + +filesync(Module, Name) -> + call(Module, Name, filesync). + +info(Module, Name) -> + call(Module, Name, info). + +reset(Module, Name) -> + call(Module, Name, reset). + +%%%----------------------------------------------------------------- +%%% Handler being added +adding_handler(#{id:=Name,module:=Module}=Config) -> + HConfig0 = maps:get(config, Config, #{}), + HandlerConfig0 = maps:without(?CONFIG_KEYS,HConfig0), + case Module:check_config(Name,set,undefined,HandlerConfig0) of + {ok,HandlerConfig} -> + ModifiedCommon = maps:with(?CONFIG_KEYS,HandlerConfig), + CommonConfig0 = maps:with(?CONFIG_KEYS,HConfig0), + CommonConfig = maps:merge( + maps:merge(get_default_config(), CommonConfig0), + ModifiedCommon), + case check_config(CommonConfig) of + ok -> + HConfig = maps:merge(CommonConfig,HandlerConfig), + start(Config#{config => HConfig}); + {error,Faulty} -> + {error,{invalid_config,Module,Faulty}} + end; + Error -> + Error + end. + +%%%----------------------------------------------------------------- +%%% Handler being removed +removing_handler(#{id:=Name, module:=Module}) -> + case whereis(?name_to_reg_name(Module,Name)) of + undefined -> + ok; + Pid -> + %% We don't want to do supervisor:terminate_child here + %% since we need to distinguish this explicit stop from a + %% system termination in order to avoid circular attempts + %% at removing the handler (implying deadlocks and + %% timeouts). + %% And we don't need to do supervisor:delete_child, since + %% the restart type is temporary, which means that the + %% child specification is automatically removed from the + %% supervisor when the process dies. + _ = gen_server:call(Pid, stop), + ok + end. + +%%%----------------------------------------------------------------- +%%% Updating handler config +changing_config(SetOrUpdate, + #{id:=Name,config:=OldHConfig,module:=Module}, + NewConfig0) -> + NewHConfig0 = maps:get(config, NewConfig0, #{}), + OldHandlerConfig = maps:without(?CONFIG_KEYS++?READ_ONLY_KEYS,OldHConfig), + NewHandlerConfig0 = maps:without(?CONFIG_KEYS++?READ_ONLY_KEYS,NewHConfig0), + case Module:check_config(Name, SetOrUpdate, + OldHandlerConfig,NewHandlerConfig0) of + {ok, NewHandlerConfig} -> + ModifiedCommon = maps:with(?CONFIG_KEYS,NewHandlerConfig), + NewCommonConfig0 = maps:with(?CONFIG_KEYS,NewHConfig0), + CommonDefault = + case SetOrUpdate of + set -> + get_default_config(); + update -> + maps:with(?CONFIG_KEYS,OldHConfig) + end, + NewCommonConfig = maps:merge( + maps:merge(CommonDefault,NewCommonConfig0), + ModifiedCommon), + case check_config(NewCommonConfig) of + ok -> + ReadOnly = maps:with(?READ_ONLY_KEYS,OldHConfig), + NewHConfig = maps:merge( + maps:merge(NewCommonConfig,NewHandlerConfig), + ReadOnly), + NewConfig = NewConfig0#{config=>NewHConfig}, + HPid = maps:get(handler_pid,OldHConfig), + case call(HPid, {change_config,NewConfig}) of + ok -> {ok,NewConfig}; + Error -> Error + end; + {error,Faulty} -> + {error,{invalid_config,Module,Faulty}} + end; + Error -> + Error + end. + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). + +log(LogEvent, Config = #{id := Name, + config := #{handler_pid := HPid, + mode_tab := ModeTab}}) -> + %% if the handler has crashed, we must drop this event + %% and hope the handler restarts so we can try again + true = is_process_alive(HPid), + Bin = log_to_binary(LogEvent, Config), + call_cast_or_drop(Name, HPid, ModeTab, Bin). + +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +filter_config(#{config:=HConfig}=Config) -> + Config#{config=>maps:without(?READ_ONLY_KEYS,HConfig)}. + +%%%----------------------------------------------------------------- +%%% Start the handler process +%%% +%%% The process must always exist if the handler is registered with +%%% logger (and must not exist if the handler is not registered). +%%% +%%% The handler process is linked to logger_sup, which is part of the +%%% kernel application's supervision tree. +start(#{id := Name} = Config0) -> + ChildSpec = + #{id => Name, + start => {?MODULE, start_link, [Config0]}, + restart => temporary, + shutdown => 2000, + type => worker, + modules => [?MODULE]}, + case supervisor:start_child(logger_sup, ChildSpec) of + {ok,Pid,Config} -> + ok = logger_handler_watcher:register_handler(Name,Pid), + {ok,Config}; + Error -> + Error + end. + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init(#{id := Name, module := Module, + formatter := Formatter, config := HConfig0} = Config0) -> + RegName = ?name_to_reg_name(Module,Name), + register(RegName, self()), + process_flag(trap_exit, true), + process_flag(message_queue_data, off_heap), + + ?init_test_hooks(), + ?start_observation(Name), + + case Module:init(Name, HConfig0) of + {ok,HState} -> + try ets:new(Name, [public]) of + ModeTab -> + ?set_mode(ModeTab, async), + T0 = ?timestamp(), + HConfig = HConfig0#{handler_pid => self(), + mode_tab => ModeTab}, + Config = Config0#{config => HConfig}, + proc_lib:init_ack({ok,self(),Config}), + %% Storing common config in state to avoid copying + %% (sending) the config data for each log message + CommonConfig = maps:with(?CONFIG_KEYS,HConfig), + State = + ?merge_with_stats( + CommonConfig#{id => Name, + module => Module, + mode_tab => ModeTab, + mode => async, + ctrl_sync_count => + ?CONTROLLER_SYNC_INTERVAL, + last_qlen => 0, + last_log_ts => T0, + last_op => sync, + burst_win_ts => T0, + burst_msg_count => 0, + formatter => Formatter, + handler_state => HState}), + State1 = set_repeated_filesync(State), + unset_restart_flag(State1), + gen_server:enter_loop(?MODULE, [], State1) + catch + _:Error -> + unregister(RegName), + error_notify({init_handler,Name,Error}), + proc_lib:init_ack(Error) + end; + Error -> + unregister(RegName), + error_notify({init_handler,Name,Error}), + proc_lib:init_ack(Error) + end. + +%% This is the synchronous log event. +handle_call({log, Bin}, _From, State) -> + {Result,State1} = do_log(Bin, call, State), + %% Result == ok | dropped + {reply,Result, State1}; + +handle_call(filesync, _From, State = #{id := Name, + module := Module, + handler_state := HandlerState}) -> + {Result,HandlerState1} = Module:filesync(Name,sync,HandlerState), + {reply, Result, State#{handler_state=>HandlerState1, last_op=>sync}}; + +handle_call({change_config, #{formatter:=Formatter, config:=NewHConfig}}, _From, + State = #{filesync_repeat_interval := FSyncInt0}) -> + %% In the future, if handler_state must be updated due to config + %% change, then we need to add a callback to Module here. + CommonConfig = maps:with(?CONFIG_KEYS,NewHConfig), + State1 = maps:merge(State, CommonConfig), + State2 = + case maps:get(filesync_repeat_interval, NewHConfig) of + FSyncInt0 -> + State1; + _FSyncInt1 -> + set_repeated_filesync(cancel_repeated_filesync(State1)) + end, + {reply, ok, State2#{formatter:=Formatter}}; + +handle_call(info, _From, State) -> + {reply, State, State}; + +handle_call(reset, _From, + #{id:=Name,module:=Module,handler_state:=HandlerState}=State) -> + State1 = ?merge_with_stats(State), + {reply, ok, State1#{last_qlen => 0, + last_log_ts => ?timestamp(), + handler_state => Module:reset_state(Name,HandlerState)}}; + +handle_call(stop, _From, State) -> + {stop, {shutdown,stopped}, ok, State}. + +%% This is the asynchronous log event. +handle_cast({log, Bin}, State) -> + {_,State1} = do_log(Bin, cast, State), + {noreply, State1}; + +%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this +%% clause gets called repeatedly by the handler. In order to +%% guarantee that a filesync *always* happens after the last log +%% event, the repeat operation must be active! +handle_cast(repeated_filesync,State = #{filesync_repeat_interval := no_repeat}) -> + %% This clause handles a race condition which may occur when + %% config changes filesync_repeat_interval from an integer value + %% to no_repeat. + {noreply,State}; +handle_cast(repeated_filesync, + State = #{id := Name, + module := Module, + handler_state := HandlerState, + last_op := LastOp}) -> + State1 = + if LastOp == sync -> + State; + true -> + {_,HS} = Module:filesync(Name, async, HandlerState), + State#{handler_state => HS, last_op => sync} + end, + {noreply,set_repeated_filesync(State1)}. + +handle_info(Info, #{id := Name, module := Module, + handler_state := HandlerState} = State) -> + {noreply,State#{handler_state => Module:handle_info(Name,Info,HandlerState)}}. + +terminate(Reason, State = #{id := Name, + module := Module, + handler_state := HandlerState}) -> + _ = cancel_repeated_filesync(State), + _ = Module:terminate(Name, Reason, HandlerState), + ok = stop_or_restart(Name, Reason, State), + unregister(?name_to_reg_name(Module, Name)), + ok. + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + + +%%%----------------------------------------------------------------- +%%% Internal functions +call(Module, Name, Op) when is_atom(Name) -> + call(?name_to_reg_name(Module,Name), Op); +call(_, Name, Op) -> + {error,{badarg,{Op,[Name]}}}. + +call(Server, Msg) -> + try + gen_server:call(Server, Msg, ?DEFAULT_CALL_TIMEOUT) + catch + _:{timeout,_} -> {error,handler_busy} + end. + +%% check for overload between every event (and set Mode to async, +%% sync or drop accordingly), but never flush the whole mailbox +%% before LogWindowSize events have been handled +do_log(Bin, CallOrCast, State = #{id:=Name, mode:=Mode0}) -> + T1 = ?timestamp(), + + %% check if the handler is getting overloaded, or if it's + %% recovering from overload (the check must be done for each + %% event to react quickly to large bursts of events and + %% to ensure that the handler can never end up in drop mode + %% with an empty mailbox, which would stop operation) + {Mode1,QLen,Mem,State1} = check_load(State), + + if (Mode1 == drop) andalso (Mode0 =/= drop) -> + log_handler_info(Name, "Handler ~p switched to drop mode", + [Name], State); + (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> + log_handler_info(Name, "Handler ~p switched to ~w mode", + [Name,Mode1], State); + true -> + ok + end, + + %% kill the handler if it can't keep up with the load + kill_if_choked(Name, QLen, Mem, State), + + if Mode1 == flush -> + flush(Name, QLen, T1, State1); + true -> + write(Name, Mode1, T1, Bin, CallOrCast, State1) + end. + +%% this clause is called by do_log/3 after an overload check +%% has been performed, where QLen > FlushQLen +flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> + %% flush messages in the mailbox (a limited number in + %% order to not cause long delays) + NewFlushed = flush_log_events(?FLUSH_MAX_N), + + %% write info in log about flushed messages + log_handler_info(Name, "Handler ~p flushed ~w log events", + [Name,NewFlushed], State), + + %% because of the receive loop when flushing messages, the + %% handler will be scheduled out often and the mailbox could + %% grow very large, so we'd better check the queue again here + {_,_QLen1} = process_info(self(), message_queue_len), + ?observe(Name,{max_qlen,_QLen1}), + + %% Add 1 for the current log event + ?observe(Name,{flushed,NewFlushed+1}), + + State1 = ?update_max_time(?diff_time(T1,_T0),State), + State2 = ?update_max_qlen(_QLen1,State1), + {dropped,?update_other(flushed,FLUSHED,NewFlushed, + State2#{mode => ?set_mode(ModeTab,async), + last_qlen => 0, + last_log_ts => T1})}. + +%% this clause is called to write to file +write(Name, Mode, T1, Bin, _CallOrCast, + State = #{module := Module, + handler_state := HandlerState, + mode_tab := ModeTab, + ctrl_sync_count := CtrlSync, + last_qlen := LastQLen, + last_log_ts := T0}) -> + %% check if we need to limit the number of writes + %% during a burst of log events + {DoWrite,State1} = limit_burst(State), + + %% only log synhrounously every ?CONTROLLER_SYNC_INTERVAL time, to + %% give the handler time between writes so it can keep up with + %% incoming messages + {Result,LastQLen1,HandlerState1} = + if DoWrite, CtrlSync == 0 -> + ?observe(Name,{_CallOrCast,1}), + {_,HS1} = Module:write(Name, sync, Bin, HandlerState), + {ok,element(2, process_info(self(), message_queue_len)),HS1}; + DoWrite -> + ?observe(Name,{_CallOrCast,1}), + {_,HS1} = Module:write(Name, async, Bin, HandlerState), + {ok,LastQLen,HS1}; + not DoWrite -> + ?observe(Name,{flushed,1}), + {dropped,LastQLen,HandlerState} + end, + + %% Check if the time since the previous log event is long enough - + %% and the queue length small enough - to assume the mailbox has + %% been emptied, and if so, do filesync operation and reset mode to + %% async. Note that this is the best we can do to detect an idle + %% handler without setting a timer after each log call/cast. If the + %% time between two consecutive log events is fast and no new + %% event comes in after the last one, idle state won't be detected! + Time = ?diff_time(T1,T0), + State2 = + if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso + (Time > ?IDLE_DETECT_TIME_USEC) -> + {_,HS2} = Module:filesync(Name,async,HandlerState), + State1#{mode => ?change_mode(ModeTab, Mode, async), + burst_msg_count => 0, + handler_state => HS2}; + true -> + State1#{mode => Mode, handler_state => HandlerState1} + end, + State3 = ?update_calls_or_casts(_CallOrCast,1,State2), + State4 = ?update_max_qlen(LastQLen1,State3), + State5 = + ?update_max_time(Time, + State4#{last_qlen := LastQLen1, + last_log_ts => T1, + last_op => write, + ctrl_sync_count => + if CtrlSync==0 -> ?CONTROLLER_SYNC_INTERVAL; + true -> CtrlSync-1 + end}), + {Result,State5}. + +log_handler_info(Name, Format, Args, #{module:=Module, + formatter:=Formatter, + handler_state:=HandlerState}) -> + Config = #{formatter=>Formatter}, + Meta = #{time=>erlang:system_time(microsecond)}, + Bin = log_to_binary(#{level => notice, + msg => {Format,Args}, + meta => Meta}, Config), + _ = Module:write(Name, async, Bin, HandlerState), + ok. %%%----------------------------------------------------------------- %%% Convert log data on any form to binary @@ -94,46 +537,65 @@ string_to_binary(String) -> throw(Error) end. - %%%----------------------------------------------------------------- %%% Check that the configuration term is valid -check_common_config({mode_tab,_Tid}) -> - valid; -check_common_config({handler_pid,Pid}) when is_pid(Pid) -> - valid; - -check_common_config({sync_mode_qlen,N}) when is_integer(N) -> - valid; -check_common_config({drop_mode_qlen,N}) when is_integer(N) -> - valid; -check_common_config({flush_qlen,N}) when is_integer(N) -> - valid; - -check_common_config({burst_limit_enable,Bool}) when Bool == true; - Bool == false -> - valid; -check_common_config({burst_limit_max_count,N}) when is_integer(N) -> - valid; -check_common_config({burst_limit_window_time,N}) when is_integer(N) -> - valid; - -check_common_config({overload_kill_enable,Bool}) when Bool == true; - Bool == false -> - valid; -check_common_config({overload_kill_qlen,N}) when is_integer(N) -> - valid; -check_common_config({overload_kill_mem_size,N}) when is_integer(N) -> - valid; -check_common_config({overload_kill_restart_after,NorA}) when is_integer(NorA); - NorA == infinity -> - valid; - -check_common_config({filesync_repeat_interval,NorA}) when is_integer(NorA); - NorA == no_repeat -> - valid; -check_common_config(_) -> - invalid. +check_config(Config) when is_map(Config) -> + case check_common_config(maps:to_list(Config)) of + ok -> + case overload_levels_ok(Config) of + true -> + ok; + false -> + Faulty = maps:with([sync_mode_qlen, + drop_mode_qlen, + flush_qlen],Config), + {error,{invalid_levels,Faulty}} + end; + Error -> + Error + end. + +check_common_config([{sync_mode_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{drop_mode_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{flush_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{burst_limit_enable,Bool}|Config]) when is_boolean(Bool) -> + check_common_config(Config); +check_common_config([{burst_limit_max_count,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{burst_limit_window_time,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{overload_kill_enable,Bool}|Config]) when is_boolean(Bool) -> + check_common_config(Config); +check_common_config([{overload_kill_qlen,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{overload_kill_mem_size,N}|Config]) when is_integer(N) -> + check_common_config(Config); +check_common_config([{overload_kill_restart_after,NorA}|Config]) + when is_integer(NorA); NorA == infinity -> + check_common_config(Config); +check_common_config([{filesync_repeat_interval,NorA}|Config]) + when is_integer(NorA); NorA == no_repeat -> + check_common_config(Config); +check_common_config([{Key,Value}|_]) -> + {error,#{Key=>Value}}; +check_common_config([]) -> + ok. +get_default_config() -> + #{sync_mode_qlen => ?SYNC_MODE_QLEN, + drop_mode_qlen => ?DROP_MODE_QLEN, + flush_qlen => ?FLUSH_QLEN, + burst_limit_enable => ?BURST_LIMIT_ENABLE, + burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable => ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen => ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, + filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. %%%----------------------------------------------------------------- %%% Overload Protection @@ -146,15 +608,13 @@ call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) -> async -> gen_server:cast(HandlerPid, {log,Bin}); sync -> - try gen_server:call(HandlerPid, {log,Bin}, ?DEFAULT_CALL_TIMEOUT) of - %% if return value from call == dropped, the - %% message has been flushed by handler and should - %% therefore not be counted as dropped in stats - ok -> ok; - dropped -> ok - catch - _:{timeout,_} -> - ?observe(_Name,{dropped,1}) + case call(HandlerPid, {log,Bin}) of + ok -> + ok; + _Other -> + %% dropped or {error,handler_busy} + ?observe(_Name,{dropped,1}), + ok end; drop -> ?observe(_Name,{dropped,1}) @@ -165,10 +625,8 @@ call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) -> end, ok. -handler_exit(_Name, Reason) -> - exit(Reason). - -set_restart_flag(Name, Module) -> +set_restart_flag(#{id := Name, module := Module} = State) -> + log_handler_info(Name, "Handler ~p overloaded and stopping", [Name], State), Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), spawn(fun() -> register(Flag, self()), @@ -176,14 +634,14 @@ set_restart_flag(Name, Module) -> end), ok. -unset_restart_flag(Name, Module) -> +unset_restart_flag(#{id := Name, module := Module} = State) -> Flag = list_to_atom(lists:concat([Module,"_",Name,"_restarting"])), case whereis(Flag) of undefined -> - false; + ok; Pid -> exit(Pid, kill), - true + log_handler_info(Name, "Handler ~p restarted", [Name], State) end. check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode, @@ -221,46 +679,41 @@ check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode, ?update_other(flushes,FLUSHES,_NewFlushes, State1#{last_qlen => QLen})}. -limit_burst(#{burst_limit_enable := false}) -> - {true,0,0}; +limit_burst(#{burst_limit_enable := false}=State) -> + {true,State}; limit_burst(#{burst_win_ts := BurstWinT0, burst_msg_count := BurstMsgCount, burst_limit_window_time := BurstLimitWinTime, - burst_limit_max_count := BurstLimitMaxCnt}) -> + burst_limit_max_count := BurstLimitMaxCnt} = State) -> if (BurstMsgCount >= BurstLimitMaxCnt) -> %% the limit for allowed messages has been reached BurstWinT1 = ?timestamp(), case ?diff_time(BurstWinT1,BurstWinT0) of BurstCheckTime when BurstCheckTime < (BurstLimitWinTime*1000) -> %% we're still within the burst time frame - {false,BurstWinT0,BurstMsgCount}; + {false,?update_other(burst_drops,BURSTS,1,State)}; _BurstCheckTime -> %% burst time frame passed, reset counters - {true,BurstWinT1,0} + {true,State#{burst_win_ts => BurstWinT1, + burst_msg_count => 0}} end; true -> %% the limit for allowed messages not yet reached - {true,BurstWinT0,BurstMsgCount+1} + {true,State#{burst_win_ts => BurstWinT0, + burst_msg_count => BurstMsgCount+1}} end. -kill_if_choked(Name, QLen, Mem, HandlerMod, - State = #{overload_kill_enable := KillIfOL, - overload_kill_qlen := OLKillQLen, - overload_kill_mem_size := OLKillMem}) -> +kill_if_choked(Name, QLen, Mem, State = #{overload_kill_enable := KillIfOL, + overload_kill_qlen := OLKillQLen, + overload_kill_mem_size := OLKillMem}) -> if KillIfOL andalso ((QLen > OLKillQLen) orelse (Mem > OLKillMem)) -> - HandlerMod:log_handler_info(Name, - "Handler ~p overloaded and stopping", - [Name], State), - set_restart_flag(Name, HandlerMod), - handler_exit(Name, {shutdown,{overloaded,Name,QLen,Mem}}); + set_restart_flag(State), + exit({shutdown,{overloaded,Name,QLen,Mem}}); true -> ok end. -flush_log_events() -> - flush_log_events(-1). - flush_log_events(Limit) -> process_flag(priority, high), Flushed = flush_log_events(0, Limit), @@ -283,16 +736,29 @@ flush_log_events(N, Limit) -> 0 -> N end. -cancel_timer(TRef) when is_atom(TRef) -> ok; -cancel_timer(TRef) -> timer:cancel(TRef). +set_repeated_filesync(#{filesync_repeat_interval:=FSyncInt} = State) + when is_integer(FSyncInt) -> + {ok,TRef} = timer:apply_after(FSyncInt, gen_server, cast, + [self(),repeated_filesync]), + State#{rep_sync_tref=>TRef}; +set_repeated_filesync(State) -> + State. +cancel_repeated_filesync(State) -> + case maps:take(rep_sync_tref,State) of + {TRef,State1} -> + _ = timer:cancel(TRef), + State1; + error -> + State + end. stop_or_restart(Name, {shutdown,Reason={overloaded,_Name,_QLen,_Mem}}, #{overload_kill_restart_after := RestartAfter}) -> %% If we're terminating because of an overload situation (see - %% logger_h_common:kill_if_choked/4), we need to remove the handler - %% and set a restart timer. A separate process must perform this - %% in order to avoid deadlock. + %% kill_if_choked/4), we need to remove the handler and set a + %% restart timer. A separate process must perform this in order to + %% avoid deadlock. HandlerPid = self(), ConfigResult = logger:get_handler_config(Name), RemoveAndRestart = @@ -334,6 +800,3 @@ overload_levels_ok(HandlerConfig) -> error_notify(Term) -> ?internal_log(error, Term). - -info_notify(Term) -> - ?internal_log(info, Term). diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl index e0a7b6e3ca..261b0a6246 100644 --- a/lib/kernel/src/logger_h_common.hrl +++ b/lib/kernel/src/logger_h_common.hrl @@ -137,7 +137,7 @@ ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}), ets:insert(?TEST_HOOKS_TAB, {file_write,ok}), ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}), - ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}), + ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}), ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})). -define(set_internal_log(MOD_FUNC), @@ -150,7 +150,7 @@ ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}), ets:insert(?TEST_HOOKS_TAB, {file_write,ok}), ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}), - ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}), + ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}), ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})). -define(internal_log(TYPE, TERM), @@ -171,11 +171,11 @@ [{_,ERROR}] -> ERROR catch _:_ -> file:datasync(DEVICE) end). - -define(disk_log_blog(LOG, DATA), - try ets:lookup(?TEST_HOOKS_TAB, disk_log_blog) of - [{_,ok}] -> disk_log:blog(LOG, DATA); + -define(disk_log_write(LOG, MODE, DATA), + try ets:lookup(?TEST_HOOKS_TAB, disk_log_write) of + [{_,ok}] -> disk_log_write(LOG, MODE, DATA); [{_,ERROR}] -> ERROR - catch _:_ -> disk_log:blog(LOG, DATA) end). + catch _:_ -> disk_log_write(LOG, MODE, DATA) end). -define(disk_log_sync(LOG), try ets:lookup(?TEST_HOOKS_TAB, disk_log_sync) of @@ -194,7 +194,7 @@ -define(internal_log(TYPE, TERM), logger:internal_log(TYPE, TERM)). -define(file_write(DEVICE, DATA), file:write(DEVICE, DATA)). -define(file_datasync(DEVICE), file:datasync(DEVICE)). - -define(disk_log_blog(LOG, DATA), disk_log:blog(LOG, DATA)). + -define(disk_log_write(LOG, MODE, DATA), disk_log_write(LOG, MODE, DATA)). -define(disk_log_sync(LOG), disk_log:sync(LOG)). -define(DEFAULT_CALL_TIMEOUT, 10000). -endif. @@ -210,7 +210,7 @@ -ifdef(SAVE_STATS). -define(merge_with_stats(STATE), STATE#{flushes => 0, flushed => 0, drops => 0, - casts => 0, calls => 0, + burst_drops => 0, casts => 0, calls => 0, max_qlen => 0, max_time => 0}). -define(update_max_qlen(QLEN, STATE), diff --git a/lib/kernel/src/logger_simple_h.erl b/lib/kernel/src/logger_simple_h.erl index 8b51dd8569..fe181722f3 100644 --- a/lib/kernel/src/logger_simple_h.erl +++ b/lib/kernel/src/logger_simple_h.erl @@ -50,7 +50,6 @@ removing_handler(#{id:=simple}) -> ok; Pid -> Ref = erlang:monitor(process,Pid), - unlink(Pid), Pid ! stop, receive {'DOWN',Ref,process,Pid,_} -> ok @@ -99,7 +98,11 @@ loop(Buffer) -> replay_buffer(Buffer); _ -> ok - end; + end, + %% Before stopping, we unlink the logger process to avoid + %% an unexpected EXIT message + unlink(whereis(logger)), + ok; {log,#{msg:=_,meta:=#{time:=_}}=Log} -> do_log(Log), loop(update_buffer(Buffer,Log)); diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 42e0f5caf4..63d1dbaba2 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -19,8 +19,6 @@ %% -module(logger_std_h). --behaviour(gen_server). - -include("logger.hrl"). -include("logger_internal.hrl"). -include("logger_h_common.hrl"). @@ -28,52 +26,28 @@ -include_lib("kernel/include/file.hrl"). %% API --export([start_link/3, info/1, filesync/1, reset/1]). +-export([info/1, filesync/1, reset/1]). -%% gen_server and proc_lib callbacks --export([init/1, handle_call/3, handle_cast/2, handle_info/2, - terminate/2, code_change/3]). +%% logger_h_common callbacks +-export([init/2, check_config/4, reset_state/2, + filesync/3, write/4, handle_info/3, terminate/3]). %% logger callbacks -export([log/2, adding_handler/1, removing_handler/1, changing_config/3, filter_config/1]). -%% handler internal --export([log_handler_info/4]). - %%%=================================================================== %%% API %%%=================================================================== %%%----------------------------------------------------------------- -%%% Start a standard handler process and link to caller. -%%% This function is called by the kernel supervisor when this -%%% handler process gets added --spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when - Name :: atom(), - Config :: logger:handler_config(), - HandlerState :: map(), - Pid :: pid(), - Reason :: term(). - -start_link(Name, Config, HandlerState) -> - proc_lib:start_link(?MODULE,init,[[Name,Config,HandlerState]]). - -%%%----------------------------------------------------------------- %%% -spec filesync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -filesync(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - filesync, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; filesync(Name) -> - {error,{badarg,{filesync,[Name]}}}. + logger_h_common:filesync(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -82,15 +56,8 @@ filesync(Name) -> Info :: term(), Reason :: handler_busy | {badarg,term()}. -info(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - info, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; info(Name) -> - {error,{badarg,{info,[Name]}}}. + logger_h_common:info(?MODULE,Name). %%%----------------------------------------------------------------- %%% @@ -98,47 +65,75 @@ info(Name) -> Name :: atom(), Reason :: handler_busy | {badarg,term()}. -reset(Name) when is_atom(Name) -> - try - gen_server:call(?name_to_reg_name(?MODULE,Name), - reset, ?DEFAULT_CALL_TIMEOUT) - catch - _:{timeout,_} -> {error,handler_busy} - end; reset(Name) -> - {error,{badarg,{reset,[Name]}}}. - + logger_h_common:reset(?MODULE,Name). %%%=================================================================== -%%% logger callbacks +%%% logger callbacks - just forward to logger_h_common %%%=================================================================== %%%----------------------------------------------------------------- %%% Handler being added -adding_handler(#{id:=Name}=Config) -> - case check_config(adding, Config) of - {ok, #{config:=HConfig}=Config1} -> - %% create initial handler state by merging defaults with config - HState = maps:merge(get_init_state(), HConfig), - case logger_h_common:overload_levels_ok(HState) of - true -> - start(Name, Config1, HState); - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = HState, - {error,{invalid_levels,{SMQL,DMQL,FQL}}} - end; +-spec adding_handler(Config) -> {ok,Config} | {error,Reason} when + Config :: logger:handler_config(), + Reason :: term(). + +adding_handler(Config) -> + logger_h_common:adding_handler(Config). + +%%%----------------------------------------------------------------- +%%% Updating handler config +-spec changing_config(SetOrUpdate, OldConfig, NewConfig) -> + {ok,Config} | {error,Reason} when + SetOrUpdate :: set | update, + OldConfig :: logger:handler_config(), + NewConfig :: logger:handler_config(), + Config :: logger:handler_config(), + Reason :: term(). + +changing_config(SetOrUpdate, OldConfig, NewConfig) -> + logger_h_common:changing_config(SetOrUpdate, OldConfig, NewConfig). + +%%%----------------------------------------------------------------- +%%% Handler being removed +-spec removing_handler(Config) -> ok when + Config :: logger:handler_config(). + +removing_handler(Config) -> + logger_h_common:removing_handler(Config). + +%%%----------------------------------------------------------------- +%%% Log a string or report +-spec log(LogEvent, Config) -> ok when + LogEvent :: logger:log_event(), + Config :: logger:handler_config(). + +log(LogEvent, Config) -> + logger_h_common:log(LogEvent, Config). + +%%%----------------------------------------------------------------- +%%% Remove internal fields from configuration +-spec filter_config(Config) -> Config when + Config :: logger:handler_config(). + +filter_config(Config) -> + logger_h_common:filter_config(Config). + +%%%=================================================================== +%%% logger_h_common callbacks +%%%=================================================================== +init(Name, #{type := Type}) -> + case open_log_file(Name, Type) of + {ok,FileCtrlPid} -> + {ok,#{type=>Type,file_ctrl_pid=>FileCtrlPid}}; Error -> Error end. -%%%----------------------------------------------------------------- -%%% Updating handler config -changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) -> +check_config(_Name,set,undefined,NewHConfig) -> + check_config(maps:merge(get_default_config(),NewHConfig)); +check_config(_Name,SetOrUpdate,OldHConfig,NewHConfig0) -> WriteOnce = maps:with([type],OldHConfig), - ReadOnly = maps:with([handler_pid,mode_tab],OldHConfig), - NewHConfig0 = maps:get(config, NewConfig, #{}), Default = case SetOrUpdate of set -> @@ -148,48 +143,24 @@ changing_config(SetOrUpdate,OldConfig=#{config:=OldHConfig},NewConfig) -> OldHConfig end, - %% Allow (accidentially) included read-only fields - just overwrite them - NewHConfig = maps:merge(maps:merge(Default, NewHConfig0),ReadOnly), + NewHConfig = maps:merge(Default, NewHConfig0), - %% But fail if write-once fields are changed + %% Fail if write-once fields are changed case maps:with([type],NewHConfig) of WriteOnce -> - changing_config1(maps:get(handler_pid,OldHConfig), - OldConfig, - NewConfig#{config=>NewHConfig}); + check_config(NewHConfig); Other -> - {error,{illegal_config_change,#{config=>WriteOnce},#{config=>Other}}} + {error,{illegal_config_change,?MODULE,WriteOnce,Other}} end. -changing_config1(HPid, OldConfig, NewConfig) -> - case check_config(changing, NewConfig) of - Result = {ok,NewConfig1} -> - try gen_server:call(HPid, {change_config,OldConfig,NewConfig1}, - ?DEFAULT_CALL_TIMEOUT) of - ok -> Result; - HError -> HError - catch - _:{timeout,_} -> {error,handler_busy} - end; - Error -> - Error - end. - -check_config(adding, Config) -> - %% Merge in defaults on handler level - HConfig0 = maps:get(config, Config, #{}), - HConfig = maps:merge(get_default_config(),HConfig0), +check_config(#{type:=Type}=HConfig) -> case check_h_config(maps:to_list(HConfig)) of + ok when is_atom(Type) -> + {ok,HConfig#{filesync_repeat_interval=>no_repeat}}; ok -> - {ok,Config#{config=>HConfig}}; - Error -> - Error - end; -check_config(changing, Config) -> - HConfig = maps:get(config, Config, #{}), - case check_h_config(maps:to_list(HConfig)) of - ok -> {ok,Config}; - Error -> Error + {ok,HConfig}; + {error,{Key,Value}} -> + {error,{invalid_config,?MODULE,#{Key=>Value}}} end. check_h_config([{type,Type} | Config]) when Type == standard_io; @@ -200,219 +171,40 @@ check_h_config([{type,{file,File}} | Config]) when is_list(File) -> check_h_config([{type,{file,File,Modes}} | Config]) when is_list(File), is_list(Modes) -> check_h_config(Config); -check_h_config([Other | Config]) -> - case logger_h_common:check_common_config(Other) of - valid -> - check_h_config(Config); - invalid -> - {error,{invalid_config,?MODULE,Other}} - end; +check_h_config([Other | _]) -> + {error,Other}; check_h_config([]) -> ok. - -%%%----------------------------------------------------------------- -%%% Handler being removed -removing_handler(#{id:=Name}) -> - stop(Name). - -%%%----------------------------------------------------------------- -%%% Log a string or report --spec log(LogEvent, Config) -> ok when - LogEvent :: logger:log_event(), - Config :: logger:handler_config(). - -log(LogEvent, Config = #{id := Name, - config := #{handler_pid := HPid, - mode_tab := ModeTab}}) -> - %% if the handler has crashed, we must drop this event - %% and hope the handler restarts so we can try again - true = is_process_alive(HPid), - Bin = logger_h_common:log_to_binary(LogEvent, Config), - logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). - -%%%----------------------------------------------------------------- -%%% Remove internal fields from configuration -filter_config(#{config:=HConfig}=Config) -> - Config#{config=>maps:without([handler_pid,mode_tab],HConfig)}. - -%%%=================================================================== -%%% gen_server callbacks -%%%=================================================================== - -init([Name, Config = #{config := HConfig}, - State0 = #{type := Type, file_ctrl_sync_int := FileCtrlSyncInt}]) -> - RegName = ?name_to_reg_name(?MODULE,Name), - register(RegName, self()), - process_flag(trap_exit, true), - process_flag(message_queue_data, off_heap), - - ?init_test_hooks(), - ?start_observation(Name), - - case do_init(Name, Type) of - {ok,InitState} -> - try ets:new(Name, [public]) of - ModeTab -> - ?set_mode(ModeTab, async), - State = maps:merge(State0, InitState), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{ - mode_tab => ModeTab, - mode => async, - file_ctrl_sync => FileCtrlSyncInt, - last_qlen => 0, - last_log_ts => T0, - last_op => sync, - burst_win_ts => T0, - burst_msg_count => 0}), - Config1 = - Config#{config => HConfig#{handler_pid => self(), - mode_tab => ModeTab}}, - proc_lib:init_ack({ok,self(),Config1}), - gen_server:cast(self(), repeated_filesync), - gen_server:enter_loop(?MODULE, [], State1) - catch - _:Error -> - unregister(RegName), - logger_h_common:error_notify({init_handler,Name,Error}), - proc_lib:init_ack(Error) - end; - Error -> - unregister(RegName), - logger_h_common:error_notify({init_handler,Name,Error}), - proc_lib:init_ack(Error) - end. - -do_init(Name, Type) -> - case open_log_file(Name, Type) of - {ok,FileCtrlPid} -> - case logger_h_common:unset_restart_flag(Name, ?MODULE) of - true -> - %% inform about restart - gen_server:cast(self(), {log_handler_info, - "Handler ~p restarted", - [Name]}); - false -> - %% initial start - ok - end, - {ok,#{id=>Name,type=>Type,file_ctrl_pid=>FileCtrlPid}}; - Error -> - Error - end. - -%% This is the synchronous log event. -handle_call({log, Bin}, _From, State) -> - {Result,State1} = do_log(Bin, call, State), - %% Result == ok | dropped - {reply,Result, State1}; - -handle_call(filesync, _From, State = #{type := Type, - file_ctrl_pid := FileCtrlPid}) -> - if is_atom(Type) -> - {reply, ok, State}; - true -> - {reply, file_ctrl_filesync_sync(FileCtrlPid), State#{last_op=>sync}} - end; - -handle_call({change_config,_OldConfig,NewConfig}, _From, - State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(config, NewConfig, #{}), - State1 = maps:merge(State, HConfig), - case logger_h_common:overload_levels_ok(State1) of - true -> - _ = - case maps:get(filesync_repeat_interval, HConfig, undefined) of - undefined -> - ok; - no_repeat -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)); - FSyncInt0 -> - ok; - _FSyncInt1 -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, - State, - undefined)), - gen_server:cast(self(), repeated_filesync) - end, - {reply, ok, State1}; - false -> - #{sync_mode_qlen := SMQL, - drop_mode_qlen := DMQL, - flush_qlen := FQL} = State1, - {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} - end; - -handle_call(info, _From, State) -> - {reply, State, State}; - -handle_call(reset, _From, State) -> - State1 = ?merge_with_stats(State), - {reply, ok, State1#{last_qlen => 0, - last_log_ts => ?timestamp()}}; - -handle_call(stop, _From, State) -> - {stop, {shutdown,stopped}, ok, State}. - -%% This is the asynchronous log event. -handle_cast({log, Bin}, State) -> - {_,State1} = do_log(Bin, cast, State), - {noreply, State1}; - -handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> - log_handler_info(Name, Format, Args, State), - {noreply, State}; - -%% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this -%% clause gets called repeatedly by the handler. In order to -%% guarantee that a filesync *always* happens after the last log -%% event, the repeat operation must be active! -handle_cast(repeated_filesync, - State = #{type := Type, - file_ctrl_pid := FileCtrlPid, - filesync_repeat_interval := FSyncInt, - last_op := LastOp}) -> - State1 = - if not is_atom(Type), is_integer(FSyncInt) -> - %% only do filesync if something has been - %% written since last time we checked - if LastOp == sync -> - ok; - true -> - file_ctrl_filesync_async(FileCtrlPid) - end, - {ok,TRef} = - timer:apply_after(FSyncInt, gen_server,cast, - [self(),repeated_filesync]), - State#{rep_sync_tref => TRef, last_op => sync}; - true -> - State - end, - {noreply,State1}. - -handle_info({'EXIT',Pid,Why}, State = #{id := Name, type := FileInfo}) -> - case maps:get(file_ctrl_pid, State, undefined) of - Pid -> - %% file error, terminate handler - logger_h_common:handler_exit(Name, - {error,{write_failed,FileInfo,Why}}); - _Other -> - %% ignore EXIT - ok - end, - {noreply, State}; - -handle_info(_Info, State) -> - {noreply, State}. - -terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid, - type:=_FileInfo}) -> - _ = logger_h_common:cancel_timer(maps:get(rep_sync_tref, State, - undefined)), +get_default_config() -> + #{type => standard_io}. + +filesync(_Name, _Mode, #{type := Type}=State) when is_atom(Type) -> + {ok,State}; +filesync(_Name, async, #{file_ctrl_pid := FileCtrlPid} = State) -> + ok = file_ctrl_filesync_async(FileCtrlPid), + {ok,State}; +filesync(_Name, sync, #{file_ctrl_pid := FileCtrlPid} = State) -> + Result = file_ctrl_filesync_sync(FileCtrlPid), + {Result,State}. + +write(_Name, async, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) -> + ok = file_write_async(FileCtrlPid, Bin), + {ok,State}; +write(_Name, sync, Bin, #{file_ctrl_pid:=FileCtrlPid} = State) -> + Result = file_write_sync(FileCtrlPid, Bin), + {Result,State}. + +reset_state(_Name, State) -> + State. + +handle_info(_Name, {'EXIT',Pid,Why}, #{type := FileInfo, file_ctrl_pid := Pid}) -> + %% file_ctrl_pid died, file error, terminate handler + exit({error,{write_failed,FileInfo,Why}}); +handle_info(_, _, State) -> + State. + +terminate(_Name, _Reason, #{file_ctrl_pid:=FWPid}) -> case is_process_alive(FWPid) of true -> unlink(FWPid), @@ -423,17 +215,12 @@ terminate(Reason, State = #{id:=Name, file_ctrl_pid:=FWPid, ok after ?DEFAULT_CALL_TIMEOUT -> - exit(FWPid, kill) + exit(FWPid, kill), + ok end; false -> ok - end, - ok = logger_h_common:stop_or_restart(Name, Reason, State), - unregister(?name_to_reg_name(?MODULE, Name)), - ok. - -code_change(_OldVsn, State, _Extra) -> - {ok, State}. + end. %%%=================================================================== %%% Internal functions @@ -441,203 +228,6 @@ code_change(_OldVsn, State, _Extra) -> %%%----------------------------------------------------------------- %%% -get_default_config() -> - #{type => standard_io, - sync_mode_qlen => ?SYNC_MODE_QLEN, - drop_mode_qlen => ?DROP_MODE_QLEN, - flush_qlen => ?FLUSH_QLEN, - burst_limit_enable => ?BURST_LIMIT_ENABLE, - burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, - burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, - overload_kill_enable => ?OVERLOAD_KILL_ENABLE, - overload_kill_qlen => ?OVERLOAD_KILL_QLEN, - overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, - overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. - -get_init_state() -> - #{file_ctrl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN}. - -%%%----------------------------------------------------------------- -%%% Add a standard handler to the logger. -%%% This starts a dedicated handler process which should always -%%% exist if the handler is registered with logger (and should not -%%% exist if the handler is not registered). -%%% -%%% Handler specific config should be provided with a sub map associated -%%% with a key named 'config', e.g: -%%% -%%% Config = #{config => #{sync_mode_qlen => 50} -%%% -%%% The standard handler process is linked to logger_sup, which is -%%% part of the kernel application's supervision tree. -start(Name, Config, HandlerState) -> - LoggerStdH = - #{id => Name, - start => {?MODULE, start_link, [Name,Config,HandlerState]}, - restart => temporary, - shutdown => 2000, - type => worker, - modules => [?MODULE]}, - case supervisor:start_child(logger_sup, LoggerStdH) of - {ok,Pid,Config1} -> - ok = logger_handler_watcher:register_handler(Name,Pid), - {ok,Config1}; - Error -> - Error - end. - -%%%----------------------------------------------------------------- -%%% Stop and remove the handler. -stop(Name) -> - case whereis(?name_to_reg_name(?MODULE,Name)) of - undefined -> - ok; - Pid -> - %% We don't want to do supervisor:terminate_child here - %% since we need to distinguish this explicit stop from a - %% system termination in order to avoid circular attempts - %% at removing the handler (implying deadlocks and - %% timeouts). - %% And we don't need to do supervisor:delete_child, since - %% the restart type is temporary, which means that the - %% child specification is automatically removed from the - %% supervisor when the process dies. - _ = gen_server:call(Pid, stop), - ok - end. - -%%%----------------------------------------------------------------- -%%% Logging and overload control. --define(update_file_ctrl_sync(C, Interval), - if C == 0 -> Interval; - true -> C-1 end). - -%% check for overload between every event (and set Mode to async, -%% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize events have been handled -do_log(Bin, CallOrCast, State = #{id:=Name, mode:=Mode0}) -> - T1 = ?timestamp(), - - %% check if the handler is getting overloaded, or if it's - %% recovering from overload (the check must be done for each - %% event to react quickly to large bursts of events and - %% to ensure that the handler can never end up in drop mode - %% with an empty mailbox, which would stop operation) - {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), - - if (Mode1 == drop) andalso (Mode0 =/= drop) -> - log_handler_info(Name, "Handler ~p switched to drop mode", - [Name], State); - (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> - log_handler_info(Name, "Handler ~p switched to ~w mode", - [Name,Mode1], State); - true -> - ok - end, - - %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), - - if Mode1 == flush -> - flush(Name, QLen, T1, State1); - true -> - write(Name, Mode1, T1, Bin, CallOrCast, State1) - end. - -%% this clause is called by do_log/3 after an overload check -%% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> - %% flush messages in the mailbox (a limited number in - %% order to not cause long delays) - NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), - - %% write info in log about flushed messages - log_handler_info(Name, "Handler ~p flushed ~w log events", - [Name,NewFlushed], State), - - %% because of the receive loop when flushing messages, the - %% handler will be scheduled out often and the mailbox could - %% grow very large, so we'd better check the queue again here - {_,_QLen1} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,_QLen1}), - - %% Add 1 for the current log event - ?observe(Name,{flushed,NewFlushed+1}), - - State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,NewFlushed, - State1#{mode => ?set_mode(ModeTab,async), - last_qlen => 0, - last_log_ts => T1})}. - -%% this clause is called to write to file -write(_Name, Mode, T1, Bin, _CallOrCast, - State = #{mode_tab := ModeTab, - file_ctrl_pid := FileCtrlPid, - file_ctrl_sync := FileCtrlSync, - last_qlen := LastQLen, - last_log_ts := T0, - file_ctrl_sync_int := FileCtrlSyncInt}) -> - %% check if we need to limit the number of writes - %% during a burst of log events - {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - - %% only send a synhrounous event to the file controller process - %% every FileCtrlSyncInt time, to give the handler time between - %% file writes so it can keep up with incoming messages - {Result,LastQLen1} = - if DoWrite, FileCtrlSync == 0 -> - ?observe(_Name,{_CallOrCast,1}), - file_write_sync(FileCtrlPid, Bin, false), - {ok,element(2, process_info(self(), message_queue_len))}; - DoWrite -> - ?observe(_Name,{_CallOrCast,1}), - file_write_async(FileCtrlPid, Bin), - {ok,LastQLen}; - not DoWrite -> - ?observe(_Name,{flushed,1}), - {dropped,LastQLen} - end, - - %% Check if the time since the previous log event is long enough - - %% and the queue length small enough - to assume the mailbox has - %% been emptied, and if so, do filesync operation and reset mode to - %% async. Note that this is the best we can do to detect an idle - %% handler without setting a timer after each log call/cast. If the - %% time between two consecutive log events is fast and no new - %% event comes in after the last one, idle state won't be detected! - Time = ?diff_time(T1,T0), - {Mode1,BurstMsgCount1} = - if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso - (Time > ?IDLE_DETECT_TIME_USEC) -> - %% do filesync if necessary - case maps:get(type, State) of - Std when is_atom(Std) -> - ok; - _File -> - file_ctrl_filesync_async(FileCtrlPid) - end, - {?change_mode(ModeTab, Mode, async),0}; - true -> - {Mode,BurstMsgCount} - end, - State1 = - ?update_calls_or_casts(_CallOrCast,1,State), - State2 = - ?update_max_time(Time, - State1#{mode => Mode1, - last_qlen := LastQLen1, - last_log_ts => T1, - last_op => write, - burst_win_ts => BurstWinT, - burst_msg_count => BurstMsgCount1, - file_ctrl_sync => - ?update_file_ctrl_sync(FileCtrlSync, - FileCtrlSyncInt)}), - {Result,State2}. - open_log_file(HandlerName, FileInfo) -> case file_ctrl_start(HandlerName, FileInfo) of OK = {ok,_FileCtrlPid} -> OK; @@ -669,19 +259,6 @@ close_log_file(Fd) -> _ = file:close(Fd). -log_handler_info(Name, Format, Args, #{file_ctrl_pid := FileCtrlPid}) -> - Config = - case logger:get_handler_config(Name) of - {ok,Conf} -> Conf; - _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}} - end, - Meta = #{time=>erlang:system_time(microsecond)}, - Bin = logger_h_common:log_to_binary(#{level => notice, - msg => {Format,Args}, - meta => Meta}, Config), - _ = file_write_async(FileCtrlPid, Bin), - ok. - %%%----------------------------------------------------------------- %%% File control process @@ -708,24 +285,19 @@ file_write_async(Pid, Bin) -> Pid ! {log,Bin}, ok. -file_write_sync(Pid, Bin, FileSync) -> - case file_ctrl_call(Pid, {log,self(),Bin,FileSync}) of - {error,Reason} -> - {error,{write_failed,Bin,Reason}}; - Result -> - Result - end. +file_write_sync(Pid, Bin) -> + file_ctrl_call(Pid, {log,Bin}). file_ctrl_filesync_async(Pid) -> Pid ! filesync, ok. file_ctrl_filesync_sync(Pid) -> - file_ctrl_call(Pid, {filesync,self()}). + file_ctrl_call(Pid, filesync). file_ctrl_call(Pid, Msg) -> MRef = monitor(process, Pid), - Pid ! {Msg,MRef}, + Pid ! {Msg,{self(),MRef}}, receive {MRef,Result} -> demonitor(MRef, [flush]), @@ -743,74 +315,43 @@ file_ctrl_init(HandlerName, FileInfo, Starter) when is_tuple(FileInfo) -> case do_open_log_file(FileInfo) of {ok,Fd} -> Starter ! {self(),ok}, - file_ctrl_loop(Fd, file, FileName, false, ok, ok, HandlerName); + file_ctrl_loop(Fd, FileName, false, ok, ok, HandlerName); {error,Reason} -> Starter ! {self(),{error,{open_failed,FileName,Reason}}} end; file_ctrl_init(HandlerName, StdDev, Starter) -> Starter ! {self(),ok}, - file_ctrl_loop(StdDev, standard_io, StdDev, false, ok, ok, HandlerName). + file_ctrl_loop(StdDev, StdDev, false, ok, ok, HandlerName). -file_ctrl_loop(Fd, Type, DevName, Synced, +file_ctrl_loop(Fd, DevName, Synced, PrevWriteResult, PrevSyncResult, HandlerName) -> receive %% asynchronous event {log,Bin} -> - Result = if Type == file -> - write_to_dev(Fd, Bin, DevName, - PrevWriteResult, HandlerName); - true -> - io:put_chars(Fd, Bin) - end, - file_ctrl_loop(Fd, Type, DevName, false, + Fd1 = ensure(Fd, DevName), + Result = write_to_dev(Fd1, Bin, DevName, PrevWriteResult, HandlerName), + file_ctrl_loop(Fd1, DevName, false, Result, PrevSyncResult, HandlerName); %% synchronous event - {{log,From,Bin,FileSync},MRef} -> - if Type == file -> - %% check that file hasn't been deleted - CheckFile = - fun() -> {ok,_} = file:read_file_info(DevName) end, - spawn_link(CheckFile), - WResult = write_to_dev(Fd, Bin, DevName, - PrevWriteResult, HandlerName), - {Synced1,SResult} = - if not FileSync -> - {false,PrevSyncResult}; - true -> - case sync_dev(Fd, DevName, - PrevSyncResult, HandlerName) of - ok -> {true,ok}; - Error -> {false,Error} - end - end, - From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, Synced1, - WResult, SResult, HandlerName); - true -> - _ = io:put_chars(Fd, Bin), - From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, false, - ok, PrevSyncResult, HandlerName) - end; + {{log,Bin},{From,MRef}} -> + Fd1 = ensure(Fd, DevName), + Result = write_to_dev(Fd1, Bin, DevName, PrevWriteResult, HandlerName), + From ! {MRef,ok}, + file_ctrl_loop(Fd1, DevName, false, + Result, PrevSyncResult, HandlerName); - filesync when not Synced -> - Result = sync_dev(Fd, DevName, PrevSyncResult, HandlerName), - file_ctrl_loop(Fd, Type, DevName, true, + filesync -> + Fd1 = ensure(Fd, DevName), + Result = sync_dev(Fd1, DevName, Synced, PrevSyncResult, HandlerName), + file_ctrl_loop(Fd1, DevName, true, PrevWriteResult, Result, HandlerName); - filesync -> - file_ctrl_loop(Fd, Type, DevName, true, - PrevWriteResult, PrevSyncResult, HandlerName); - - {{filesync,From},MRef} -> - Result = if not Synced -> - sync_dev(Fd, DevName, PrevSyncResult, HandlerName); - true -> - ok - end, + {filesync,{From,MRef}} -> + Fd1 = ensure(Fd, DevName), + Result = sync_dev(Fd1, DevName, Synced, PrevSyncResult, HandlerName), From ! {MRef,ok}, - file_ctrl_loop(Fd, Type, DevName, true, + file_ctrl_loop(Fd1, DevName, true, PrevWriteResult, Result, HandlerName); stop -> @@ -818,26 +359,44 @@ file_ctrl_loop(Fd, Type, DevName, Synced, stopped end. -write_to_dev(Fd, Bin, FileName, PrevWriteResult, HandlerName) -> - case ?file_write(Fd, Bin) of - ok -> - ok; - PrevWriteResult -> - %% don't report same error twice - PrevWriteResult; - Error -> - logger_h_common:error_notify({HandlerName,write,FileName,Error}), - Error +%% In order to play well with tools like logrotate, we need to be able +%% to re-create the file if it has disappeared (e.g. if rotated by +%% logrotate) +ensure(Fd,DevName) when is_atom(DevName) -> + Fd; +ensure(Fd,FileName) -> + case file:read_file_info(FileName) of + {ok,_} -> + Fd; + _ -> + _ = file:close(Fd), + _ = file:close(Fd), % delayed_write cause close not to close + case do_open_log_file({file,FileName}) of + {ok,Fd1} -> + Fd1; + Error -> + exit({could_not_reopen_file,Error}) + end end. -sync_dev(Fd, DevName, PrevSyncResult, HandlerName) -> - case ?file_datasync(Fd) of - ok -> - ok; - PrevSyncResult -> - %% don't report same error twice - PrevSyncResult; - Error -> - logger_h_common:error_notify({HandlerName,filesync,DevName,Error}), - Error - end. +write_to_dev(DevName, Bin, _DevName, _PrevWriteResult, _HandlerName) + when is_atom(DevName) -> + io:put_chars(DevName, Bin); +write_to_dev(Fd, Bin, FileName, PrevWriteResult, HandlerName) -> + Result = ?file_write(Fd, Bin), + maybe_notify_error(write,Result,PrevWriteResult,FileName,HandlerName). + +sync_dev(_Fd, _FileName, true, PrevSyncResult, _HandlerName) -> + PrevSyncResult; +sync_dev(Fd, FileName, false, PrevSyncResult, HandlerName) -> + Result = ?file_datasync(Fd), + maybe_notify_error(filesync,Result,PrevSyncResult,FileName,HandlerName). + +maybe_notify_error(_Op, ok, _PrevResult, _FileName, _HandlerName) -> + ok; +maybe_notify_error(_Op, PrevResult, PrevResult, _FileName, _HandlerName) -> + %% don't report same error twice + PrevResult; +maybe_notify_error(Op, Error, _PrevResult, FileName, HandlerName) -> + logger_h_common:error_notify({HandlerName,Op,FileName,Error}), + Error. diff --git a/lib/kernel/src/net_kernel.erl b/lib/kernel/src/net_kernel.erl index 3cf11fd7b1..a9dc77837e 100644 --- a/lib/kernel/src/net_kernel.erl +++ b/lib/kernel/src/net_kernel.erl @@ -808,7 +808,8 @@ handle_info({AcceptPid, {accept_pending,MyNode,Node,Address,Type}}, State) -> _:_ -> error_logger:error_msg("~n** Cannot get connection id for node ~w~n", [Node]), - AcceptPid ! {self(),{accept_pending,nok_pending}} + AcceptPid ! {self(),{accept_pending,nok_pending}}, + {noreply, State} end end; diff --git a/lib/kernel/test/gen_tcp_misc_SUITE.erl b/lib/kernel/test/gen_tcp_misc_SUITE.erl index 04c0c48e3a..c47de58fae 100644 --- a/lib/kernel/test/gen_tcp_misc_SUITE.erl +++ b/lib/kernel/test/gen_tcp_misc_SUITE.erl @@ -1969,20 +1969,20 @@ recvtclass(_Config) -> {skip,{ipv6_not_supported,IFs}} end. -%% These version numbers are the highest noted in daily tests -%% where the test fails for a plausible reason, so -%% skip on that platform. +%% These version numbers are above the highest noted +%% in daily tests where the test fails for a plausible reason, +%% so skip on platforms of lower version, i.e they are future +%% versions where it is possible that it might not fail. %% -%% On newer versions it might be fixed, but we'll see about that -%% when machines with newer versions gets installed... -%% If the test still fails for a plausible reason these +%% When machines with newer versions gets installed, +%% if the test still fails for a plausible reason these %% version numbers simply should be increased. %% Or maybe we should change to only test on known good %% platforms - change {unix,_} to false? %% pktoptions is not supported for IPv4 recvtos_ok({unix,openbsd}, OSVer) -> not semver_lt(OSVer, {6,4,0}); -recvtos_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {17,6,0}); +recvtos_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {19,0,0}); %% Using the option returns einval, so it is not implemented. recvtos_ok({unix,freebsd}, OSVer) -> not semver_lt(OSVer, {11,2,0}); recvtos_ok({unix,sunos}, OSVer) -> not semver_lt(OSVer, {5,12,0}); @@ -1994,7 +1994,7 @@ recvtos_ok(_, _) -> false. %% pktoptions is not supported for IPv4 recvttl_ok({unix,openbsd}, OSVer) -> not semver_lt(OSVer, {6,4,0}); -recvttl_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {17,6,0}); +recvttl_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {19,0,0}); %% Using the option returns einval, so it is not implemented. recvttl_ok({unix,freebsd}, OSVer) -> not semver_lt(OSVer, {11,2,0}); recvttl_ok({unix,sunos}, OSVer) -> not semver_lt(OSVer, {5,12,0}); @@ -2005,7 +2005,7 @@ recvttl_ok(_, _) -> false. %% pktoptions is not supported for IPv6 recvtclass_ok({unix,openbsd}, OSVer) -> not semver_lt(OSVer, {6,4,0}); -recvtclass_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {17,6,0}); +recvtclass_ok({unix,darwin}, OSVer) -> not semver_lt(OSVer, {19,0,0}); recvtclass_ok({unix,sunos}, OSVer) -> not semver_lt(OSVer, {5,12,0}); %% Using the option returns einval, so it is not implemented. recvtclass_ok({unix,freebsd}, OSVer) -> not semver_lt(OSVer, {11,2,0}); diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 905c2c52c5..87b8250781 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -332,16 +332,18 @@ errors(Config) -> %%! Check how bad log_opts are handled! {error,{illegal_config_change, - #{config:=#{type:=wrap}}, - #{config:=#{type:=halt}}}} = + logger_disk_log_h, + #{type:=wrap}, + #{type:=halt}}} = logger:update_handler_config(Name1, config, #{type=>halt, file=>LogFile1}), {error,{illegal_config_change, - #{config:=#{file:=LogFile1}}, - #{config:=#{file:="newfilename"}}}} = + logger_disk_log_h, + #{file:=LogFile1}, + #{file:="newfilename"}}} = logger:update_handler_config(Name1, config, #{file=>"newfilename"}), @@ -411,20 +413,25 @@ formatter_fail(cleanup,_Config) -> ok. config_fail(_Config) -> - {error,{handler_not_added,{invalid_config,logger_disk_log_h,{bad,bad}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h,#{bad:=bad}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{bad => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h, + {invalid_levels,#{drop_mode_qlen:=1}}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{drop_mode_qlen=>1}}), - {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h, + {invalid_levels,#{sync_mode_qlen:=43, + drop_mode_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{sync_mode_qlen=>43, drop_mode_qlen=>42}}), - {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = + {error,{handler_not_added,{invalid_config,logger_disk_log_h, + {invalid_levels,#{drop_mode_qlen:=43, + flush_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_disk_log_h, #{config => #{drop_mode_qlen=>43, flush_qlen=>42}}), @@ -433,20 +440,17 @@ config_fail(_Config) -> #{filter_default=>log, formatter=>{?MODULE,self()}}), %% can't change the disk log options for a log already in use - {error,{illegal_config_change,_,_}} = + {error,{illegal_config_change,logger_disk_log_h,_,_}} = logger:update_handler_config(?MODULE,config, #{max_no_files=>2}), - %% can't change name of an existing handler - {error,{illegal_config_change,_,_}} = - logger:update_handler_config(?MODULE,id,bad), %% incorrect values of OP params {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), - {error,{invalid_levels,_}} = + {error,{invalid_config,logger_disk_log_h,{invalid_levels,_}}} = logger:update_handler_config(?MODULE,config, HConfig#{sync_mode_qlen=>100, flush_qlen=>99}), %% invalid name of config parameter - {error,{invalid_config,logger_disk_log_h,{filesync_rep_int,2000}}} = + {error,{invalid_config,logger_disk_log_h,#{filesync_rep_int:=2000}}} = logger:update_handler_config(?MODULE, config, HConfig#{filesync_rep_int => 2000}), ok. @@ -487,10 +491,11 @@ reconfig(Config) -> overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL, - log_opts := #{type := ?DISK_LOG_TYPE, - max_no_files := ?DISK_LOG_MAX_NO_FILES, - max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, - file := DiskLogFile}} = + handler_state := + #{log_opts := #{type := ?DISK_LOG_TYPE, + max_no_files := ?DISK_LOG_MAX_NO_FILES, + max_no_bytes := ?DISK_LOG_MAX_NO_BYTES, + file := DiskLogFile}}} = logger_disk_log_h:info(?MODULE), {ok,#{config := #{sync_mode_qlen := ?SYNC_MODE_QLEN, @@ -572,10 +577,11 @@ reconfig(Config) -> max_no_files => 1, max_no_bytes => 1024, file => File}}), - #{log_opts := #{type := halt, - max_no_files := 1, - max_no_bytes := 1024, - file := File}} = + #{handler_state := + #{log_opts := #{type := halt, + max_no_files := 1, + max_no_bytes := 1024, + file := File}}} = logger_disk_log_h:info(?MODULE), {ok,#{config := #{type := halt, @@ -596,13 +602,13 @@ reconfig(Config) -> %% You are not allowed to actively set the write once fields %% (type, max_no_files, max_no_bytes, file) in runtime. - {error, {illegal_config_change,_,_}} = + {error, {illegal_config_change,_,_,_}} = logger:set_handler_config(?MODULE,config,#{type=>wrap}), - {error, {illegal_config_change,_,_}} = + {error, {illegal_config_change,_,_,_}} = logger:set_handler_config(?MODULE,config,#{max_no_files=>2}), - {error, {illegal_config_change,_,_}} = + {error, {illegal_config_change,_,_,_}} = logger:set_handler_config(?MODULE,config,#{max_no_bytes=>2048}), - {error, {illegal_config_change,_,_}} = + {error, {illegal_config_change,_,_,_}} = logger:set_handler_config(?MODULE,config,#{file=>"otherfile.log"}), {ok,C7} = logger:get_handler_config(?MODULE), ct:log("C7: ~p",[C7]), @@ -630,16 +636,16 @@ sync(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,nl}}), - start_tracer([{disk_log,blog,2}, - {logger_disk_log_h,disk_log_sync,2}], - [{disk_log,blog,<<"first\n">>}, - {logger_disk_log_h,disk_log_sync}]), + start_tracer([{logger_disk_log_h,disk_log_write,3}, + {disk_log,sync,1}], + [{logger_disk_log_h,disk_log_write,<<"first\n">>}, + {disk_log,sync}]), logger:notice("first", ?domain), %% wait for automatic disk_log_sync check_tracer(?FILESYNC_REPEAT_INTERVAL*2), - %% check that if there's no repeated disk_log_sync active, + %% check that if there's no repeated filesync active, %% a disk_log_sync is still performed when handler goes idle {ok,#{config := HConfig}} = logger:get_handler_config(?MODULE), HConfig1 = HConfig#{filesync_repeat_interval => no_repeat}, @@ -652,12 +658,12 @@ sync(Config) -> %% triggered by the idle timeout between "fourth" and "fifth". timer:sleep(?IDLE_DETECT_TIME_MSEC*2), - start_tracer([{disk_log,blog,2}, - {logger_disk_log_h,disk_log_sync,2}], - [{disk_log,blog,<<"second\n">>}, - {logger_disk_log_h,disk_log_sync}, - {disk_log,blog,<<"third\n">>}, - {logger_disk_log_h,disk_log_sync}]), + start_tracer([{logger_disk_log_h,disk_log_write,3}, + {disk_log,sync,1}], + [{logger_disk_log_h,disk_log_write,<<"second\n">>}, + {disk_log,sync}, + {logger_disk_log_h,disk_log_write,<<"third\n">>}, + {disk_log,sync}]), logger:notice("second", ?domain), timer:sleep(?IDLE_DETECT_TIME_MSEC*2), @@ -667,13 +673,13 @@ sync(Config) -> try_read_file(Log, {ok,<<"first\nsecond\nthird\n">>}, 1000), - %% switch repeated disk_log_sync on and verify that the looping works + %% switch repeated filesync on and verify that the looping works SyncInt = 1000, WaitT = 4500, - OneSync = {logger_disk_log_h,handle_cast,repeated_disk_log_sync}, - %% receive 1 initial repeated_disk_log_sync, then 1 per sec - start_tracer([{logger_disk_log_h,handle_cast,2}], - [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]), + OneSync = {logger_h_common,handle_cast,repeated_filesync}, + %% receive 1 repeated_filesync per sec + start_tracer([{logger_h_common,handle_cast,2}], + [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), HConfig2 = HConfig#{filesync_repeat_interval => SyncInt}, ok = logger:update_handler_config(?MODULE, config, HConfig2), @@ -716,7 +722,7 @@ disk_log_wrap(Config) -> end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), {ok,_} = dbg:p(whereis(h_proc_name()), [c]), - {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,MaxBytes)], ct:pal("String = ~p (~w)", [Text, erts_debug:size(Text)]), @@ -734,7 +740,7 @@ disk_log_wrap(Config) -> timer:sleep(1000), dbg:stop_clear(), Received = lists:flatmap(fun({trace,_M,handle_info, - [{disk_log,_Node,_Name,What},_]}) -> + [_,{disk_log,_Node,_Name,What},_]}) -> [{trace,What}]; ({log,_}) -> [] @@ -770,7 +776,7 @@ disk_log_full(Config) -> end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), {ok,_} = dbg:p(whereis(h_proc_name()), [c]), - {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), NoOfChars = 5, Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,NoOfChars)], @@ -780,14 +786,18 @@ disk_log_full(Config) -> timer:sleep(2000), dbg:stop_clear(), Received = lists:flatmap(fun({trace,_M,handle_info, - [{disk_log,_Node,_Name,What},_]}) -> + [_,{disk_log,_Node,_Name,What},_]}) -> [{trace,What}]; ({log,_}) -> [] end, test_server:messages_get()), ct:pal("Trace =~n~p", [Received]), - [{trace,full}, - {trace,{error_status,{error,{full,_}}}}] = Received, + + %% The tail here could be an error_status notification, if the + %% last write was synchronous, but in most cases it will not be + [{trace,full}|_] = Received, + %% [{trace,full}, + %% {trace,{error_status,{error,{full,_}}}}] = Received, ok. disk_log_full(cleanup, _Config) -> dbg:stop_clear(), @@ -819,14 +829,14 @@ disk_log_events(Config) -> end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), {ok,_} = dbg:p(whereis(h_proc_name()), [c]), - {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), + {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 3, []), [whereis(h_proc_name()) ! E || E <- Events], %% wait for trace messages timer:sleep(2000), dbg:stop_clear(), Received = lists:map(fun({trace,_M,handle_info, - [Got,_]}) -> Got + [_,Got,_]}) -> Got end, test_server:messages_get()), ct:pal("Trace =~n~p", [Received]), NoOfEvents = length(Events), @@ -849,13 +859,15 @@ write_failure(Config) -> false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]), HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), - ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, HState)]), + ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, + maps:get(handler_state,HState))]), + %% ?check and ?check_no_log in this test only check for internal log events ok = log_on_remote_node(Node, "Logged1"), rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), - ?check_no_log, + ?check_no_log, % no internal log when write ok SyncRepInt = case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of true -> 5500; @@ -864,24 +876,26 @@ write_failure(Config) -> try_read_file(Log, {ok,<<"Logged1\n">>}, SyncRepInt), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,{error,no_such_log}]), ok = log_on_remote_node(Node, "Cause simple error printout"), + %% this should have caused an internal log ?check({error,{?STANDARD_HANDLER,log,LogOpts,{error,no_such_log}}}), - + ok = log_on_remote_node(Node, "No second error printout"), - ?check_no_log, + ?check_no_log, % but don't log same error twice - rpc:call(Node, ?MODULE, set_result, [disk_log_blog, + rpc:call(Node, ?MODULE, set_result, [disk_log_write, {error,{full,?STANDARD_HANDLER}}]), ok = log_on_remote_node(Node, "Cause simple error printout"), + %% this was a different error, so it should be logged ?check({error,{?STANDARD_HANDLER,log,LogOpts, {error,{full,?STANDARD_HANDLER}}}}), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]), ok = log_on_remote_node(Node, "Logged2"), rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), - ?check_no_log, + ?check_no_log, % no internal log when write ok try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, SyncRepInt), ok. write_failure(cleanup, _Config) -> @@ -901,7 +915,7 @@ sync_failure(Config) -> rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), rpc:call(Node, ?MODULE, set_result, [disk_log_sync,ok]), HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), - LogOpts = maps:get(log_opts, HState), + LogOpts = maps:get(log_opts, maps:get(handler_state,HState)), SyncInt = 500, ok = rpc:call(Node, logger, update_handler_config, @@ -1606,10 +1620,10 @@ tpl([{M,F,A}|Trace]) -> tpl([]) -> ok. -tracer({trace,_,call,{logger_disk_log_h,handle_cast,[Op|_]},Caller}, +tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]},Caller}, {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op},Caller); -tracer({trace,_,call,{Mod=disk_log,Func=blog,[_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) -> +tracer({trace,_,call,{Mod=logger_disk_log_h,Func=disk_log_write,[_,_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Data},Caller); tracer({trace,_,call,{Mod,Func,_},Caller}, {Pid,[{Mod,Func}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func},Caller); diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index b6a09f4980..eb17a6d857 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -136,11 +136,12 @@ all() -> mem_kill_new, mem_kill_std, restart_after, - handler_requests_under_load + handler_requests_under_load, + recreate_deleted_log ]. add_remove_instance_tty(_Config) -> - {error,{handler_not_added,{invalid_config,logger_std_h,{type,tty}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h,#{type:=tty}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{type => tty}, filter_default=>log, @@ -234,7 +235,7 @@ errors(Config) -> {error, {handler_not_added, - {invalid_config,logger_std_h,{type,faulty_type}}}} = + {invalid_config,logger_std_h,#{type:=faulty_type}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{type => faulty_type}}), @@ -308,25 +309,30 @@ formatter_fail(cleanup,_Config) -> logger:remove_handler(?MODULE). config_fail(_Config) -> - {error,{handler_not_added,{invalid_config,logger_std_h,{bad,bad}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h,#{bad:=bad}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{bad => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), {error,{handler_not_added,{invalid_config,logger_std_h, - {restart_type,bad}}}} = + #{restart_type:=bad}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{restart_type => bad}, filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{handler_not_added,{invalid_levels,{_,1,_}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h, + {invalid_levels,#{drop_mode_qlen:=1}}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{drop_mode_qlen=>1}}), - {error,{handler_not_added,{invalid_levels,{43,42,_}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h, + {invalid_levels,#{sync_mode_qlen:=43, + drop_mode_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{sync_mode_qlen=>43, drop_mode_qlen=>42}}), - {error,{handler_not_added,{invalid_levels,{_,43,42}}}} = + {error,{handler_not_added,{invalid_config,logger_std_h, + {invalid_levels,#{drop_mode_qlen:=43, + flush_qlen:=42}}}}} = logger:add_handler(?MODULE,logger_std_h, #{config => #{drop_mode_qlen=>43, flush_qlen=>42}}), @@ -334,15 +340,15 @@ config_fail(_Config) -> ok = logger:add_handler(?MODULE,logger_std_h, #{filter_default=>log, formatter=>{?MODULE,self()}}), - {error,{illegal_config_change,#{config:=#{type:=_}},#{config:=#{type:=_}}}} = + {error,{illegal_config_change,logger_std_h,#{type:=_},#{type:=_}}} = logger:set_handler_config(?MODULE,config, #{type=>{file,"file"}}), - {error,{invalid_levels,_}} = + {error,{invalid_config,logger_std_h,{invalid_levels,_}}} = logger:set_handler_config(?MODULE,config, #{sync_mode_qlen=>100, flush_qlen=>99}), - {error,{invalid_config,logger_std_h,{filesync_rep_int,2000}}} = + {error,{invalid_config,logger_std_h,#{filesync_rep_int:=2000}}} = logger:set_handler_config(?MODULE, config, #{filesync_rep_int => 2000}), @@ -468,8 +474,8 @@ reconfig(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), #{id := ?MODULE, - type := standard_io, - file_ctrl_pid := FileCtrlPid, + handler_state := #{type := standard_io, + file_ctrl_pid := FileCtrlPid}, sync_mode_qlen := ?SYNC_MODE_QLEN, drop_mode_qlen := ?DROP_MODE_QLEN, flush_qlen := ?FLUSH_QLEN, @@ -480,7 +486,7 @@ reconfig(Config) -> overload_kill_qlen := ?OVERLOAD_KILL_QLEN, overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, - filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL} = DefaultInfo = + filesync_repeat_interval := no_repeat} = DefaultInfo = logger_std_h:info(?MODULE), {ok, @@ -496,7 +502,7 @@ reconfig(Config) -> overload_kill_qlen := ?OVERLOAD_KILL_QLEN, overload_kill_mem_size := ?OVERLOAD_KILL_MEM_SIZE, overload_kill_restart_after := ?OVERLOAD_KILL_RESTART_AFTER, - filesync_repeat_interval := ?FILESYNC_REPEAT_INTERVAL} = + filesync_repeat_interval := no_repeat} = DefaultHConf}} = logger:get_handler_config(?MODULE), @@ -511,10 +517,10 @@ reconfig(Config) -> overload_kill_qlen => 100000, overload_kill_mem_size => 10000000, overload_kill_restart_after => infinity, - filesync_repeat_interval => no_repeat}), + filesync_repeat_interval => 5000}), #{id := ?MODULE, - type := standard_io, - file_ctrl_pid := FileCtrlPid, + handler_state := #{type := standard_io, + file_ctrl_pid := FileCtrlPid}, sync_mode_qlen := 1, drop_mode_qlen := 2, flush_qlen := 3, @@ -584,7 +590,7 @@ reconfig(Config) -> %% You are not allowed to actively set 'type' in runtime, since %% this is a write once field. - {error, {illegal_config_change,_,_}} = + {error, {illegal_config_change,logger_std_h,_,_}} = logger:set_handler_config(?MODULE,config,#{type=>standard_io}), {ok,#{config:=C6}} = logger:get_handler_config(?MODULE), ct:log("C6: ~p",[C6]), @@ -620,7 +626,7 @@ file_opts(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - #{type := OkType} = logger_std_h:info(?MODULE), + #{handler_state := #{type := OkType}} = logger_std_h:info(?MODULE), logger:notice(M1=?msg,?domain), ?check(M1), B1 = ?bin(M1), @@ -643,10 +649,8 @@ sync(Config) -> %% check repeated filesync happens start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"first\n">>}, - {logger_std_h, sync_dev}, {file,datasync}]), logger:notice("first", ?domain), @@ -655,10 +659,8 @@ sync(Config) -> %% check that explicit filesync is only done once start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"second\n">>}, - {logger_std_h, sync_dev}, {file,datasync}, {no_more,500} ]), @@ -679,13 +681,10 @@ sync(Config) -> %% triggered by the idle timeout between "thrid" and "fourth". timer:sleep(?IDLE_DETECT_TIME_MSEC*2), start_tracer([{logger_std_h, write_to_dev, 5}, - {logger_std_h, sync_dev, 4}, {file, datasync, 1}], [{logger_std_h, write_to_dev, <<"third\n">>}, - {logger_std_h, sync_dev}, {file,datasync}, {logger_std_h, write_to_dev, <<"fourth\n">>}, - {logger_std_h, sync_dev}, {file,datasync}]), logger:notice("third", ?domain), %% wait for automatic filesync @@ -697,10 +696,10 @@ sync(Config) -> %% switch repeated filesync on and verify that the looping works SyncInt = 1000, WaitT = 4500, - OneSync = {logger_std_h,handle_cast,repeated_filesync}, - %% receive 1 initial repeated_filesync, then 1 per sec - start_tracer([{logger_std_h,handle_cast,2}], - [OneSync || _ <- lists:seq(1, 1 + trunc(WaitT/SyncInt))]), + OneSync = {logger_h_common,handle_cast,repeated_filesync}, + %% receive 1 repeated_filesync per sec + start_tracer([{logger_h_common,handle_cast,2}], + [OneSync || _ <- lists:seq(1, trunc(WaitT/SyncInt))]), ok = logger:update_handler_config(?MODULE, config, #{filesync_repeat_interval => SyncInt}), @@ -1257,6 +1256,22 @@ handler_requests_under_load(Config) -> handler_requests_under_load(cleanup, _Config) -> ok = stop_handler(?MODULE). +recreate_deleted_log(Config) -> + {Log,_HConfig,_StdHConfig} = + start_handler(?MODULE, ?FUNCTION_NAME, Config), + logger:notice("first",?domain), + logger_std_h:filesync(?MODULE), + ok = file:rename(Log,Log++".old"), + logger:notice("second",?domain), + logger_std_h:filesync(?MODULE), + {ok,<<"first\n">>} = file:read_file(Log++".old"), + {ok,<<"second\n">>} = file:read_file(Log), + ok. +recreate_deleted_log(cleanup, _Config) -> + ok = stop_handler(?MODULE). + +%%%----------------------------------------------------------------- +%%% send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> receive {From,finish} -> @@ -1278,8 +1293,8 @@ send_requests(HName, TO, Reqs = [{Req,Res}|Rs]) -> %%%----------------------------------------------------------------- %%% -start_handler(Name, TTY, Config) when TTY == standard_io; - TTY == standard_error-> +start_handler(Name, TTY, _Config) when TTY == standard_io; + TTY == standard_error-> ok = logger:add_handler(Name, logger_std_h, #{config => #{type => TTY}, @@ -1533,7 +1548,7 @@ start_op_trace() -> {ok,_} = dbg:p(self(), [c]), MS1 = dbg:fun2ms(fun([_]) -> return_trace() end), - {ok,_} = dbg:tp(logger_h_common, check_load, 1, MS1), + {ok,_} = dbg:tpl(logger_h_common, check_load, 1, MS1), {ok,_} = dbg:tpl(logger_h_common, flush_log_requests, 2, []), @@ -1607,7 +1622,9 @@ analyse(Msgs) -> start_tracer(Trace,Expected) -> Pid = self(), - FileCtrlPid = maps:get(file_ctrl_pid, logger_std_h:info(?MODULE)), + FileCtrlPid = maps:get(file_ctrl_pid, + maps:get(handler_state, + logger_std_h:info(?MODULE))), dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), dbg:p(whereis(h_proc_name()),[c]), dbg:p(FileCtrlPid,[c]), @@ -1628,7 +1645,7 @@ tpl([{M,F,A}|Trace]) -> tpl([]) -> ok. -tracer({trace,_,call,{logger_std_h,handle_cast,[Op|_]}}, +tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]}}, {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op}); tracer({trace,_,call,{Mod=logger_std_h,Func=write_to_dev,[_,Data,_,_,_]}}, diff --git a/lib/kernel/test/sendfile_SUITE.erl b/lib/kernel/test/sendfile_SUITE.erl index 0c0b1cbcb6..ad060aa05c 100644 --- a/lib/kernel/test/sendfile_SUITE.erl +++ b/lib/kernel/test/sendfile_SUITE.erl @@ -341,7 +341,21 @@ t_sendfile_closeduring(Config) -> -1 end, - ok = sendfile_send({127,0,0,1}, Send, 0). + ok = sendfile_send({127,0,0,1}, Send, 0, [{active,false}]), + [] = flush(), + ok = sendfile_send({127,0,0,1}, Send, 0, [{active,true}]), + [] = flush(), + ok. + +flush() -> + lists:reverse(flush([])). + +flush(Acc) -> + receive M -> + flush([M | Acc]) + after 0 -> + Acc + end. t_sendfile_crashduring(Config) -> Filename = proplists:get_value(big_file, Config), @@ -409,12 +423,16 @@ sendfile_send(Send) -> sendfile_send(Host, Send) -> sendfile_send(Host, Send, []). sendfile_send(Host, Send, Orig) -> + sendfile_send(Host, Send, Orig, [{active,false}]). + +sendfile_send(Host, Send, Orig, SockOpts) -> + SFServer = spawn_link(?MODULE, sendfile_server, [self(), Orig]), receive {server, Port} -> - {ok, Sock} = gen_tcp:connect(Host, Port, - [binary,{packet,0}, - {active,false}]), + Opts = [binary,{packet,0}|SockOpts], + io:format("connect with opts = ~p\n", [Opts]), + {ok, Sock} = gen_tcp:connect(Host, Port, Opts), Data = case proplists:get_value(arity,erlang:fun_info(Send)) of 1 -> Send(Sock); diff --git a/lib/kernel/vsn.mk b/lib/kernel/vsn.mk index df95174c9f..35e6a16a49 100644 --- a/lib/kernel/vsn.mk +++ b/lib/kernel/vsn.mk @@ -1 +1 @@ -KERNEL_VSN = 6.1 +KERNEL_VSN = 6.1.1 diff --git a/lib/observer/src/crashdump_viewer.erl b/lib/observer/src/crashdump_viewer.erl index 0627c15b1c..97bb344cbf 100644 --- a/lib/observer/src/crashdump_viewer.erl +++ b/lib/observer/src/crashdump_viewer.erl @@ -589,9 +589,9 @@ truncated_here(Tag) -> case get(truncated) of true -> case get(last_tag) of - Tag -> % Tag == {TagType,Id} + {Tag,_Pos} -> % Tag == {TagType,Id} true; - {Tag,_Id} -> + {{Tag,_Id},_Pos} -> true; _LastTag -> truncated_earlier(Tag) @@ -846,8 +846,8 @@ do_read_file(File) -> case check_dump_version(Id) of {ok,DumpVsn} -> reset_tables(), - insert_index(Tag,Id,N1+1), - put_last_tag(Tag,""), + insert_index(Tag,Id,Pos=N1+1), + put_last_tag(Tag,"",Pos), DecodeOpts = get_decode_opts(DumpVsn), indexify(Fd,DecodeOpts,Rest,N1), end_progress(), @@ -915,23 +915,11 @@ indexify(Fd,DecodeOpts,Bin,N) -> _ -> insert_index(Tag,Id,NewPos) end, - case put_last_tag(Tag,Id) of - {?proc_heap,LastId} -> - [{_,LastPos}] = lookup_index(?proc_heap,LastId), + case put_last_tag(Tag,Id,NewPos) of + {{?proc_heap,LastId},LastPos} -> ets:insert(cdv_heap_file_chars,{LastId,N+Start+1-LastPos}); - {?literals,[]} -> - case get(truncated_reason) of - undefined -> - [{_,LastPos}] = lookup_index(?literals,[]), - ets:insert(cdv_heap_file_chars, - {literals,N+Start+1-LastPos}); - _ -> - %% Literals are truncated. Make sure we never - %% attempt to read in the literals. (Heaps that - %% references literals will show markers for - %% incomplete heaps, but will otherwise work.) - delete_index(?literals, []) - end; + {{?literals,[]},LastPos} -> + ets:insert(cdv_heap_file_chars,{literals,N+Start+1-LastPos}); _ -> ok end, indexify(Fd,DecodeOpts,Rest,N1); @@ -973,10 +961,18 @@ tag(Fd,<<>>,N,Gat,Di,Now) -> check_if_truncated() -> case get(last_tag) of - {?ende,_} -> + {{?ende,_},_} -> put(truncated,false), put(truncated_proc,false); - TruncatedTag -> + {{?literals,[]},_} -> + put(truncated,true), + put(truncated_proc,false), + %% Literals are truncated. Make sure we never + %% attempt to read in the literals. (Heaps that + %% references literals will show markers for + %% incomplete heaps, but will otherwise work.) + delete_index(?literals, []); + {TruncatedTag,_} -> put(truncated,true), find_truncated_proc(TruncatedTag) end. @@ -984,7 +980,6 @@ check_if_truncated() -> find_truncated_proc({Tag,_Id}) when Tag==?atoms; Tag==?binary; Tag==?instr_data; - Tag==?literals; Tag==?memory_status; Tag==?memory_map -> put(truncated_proc,false); @@ -2870,12 +2865,12 @@ parse_heap_term("Yc"++Line0, Addr, DecodeOpts, D0) -> %Reference-counted binary. SymbolicBin = {'#CDVBin',Start}, Term = cdvbin(Offset, Sz, SymbolicBin), D1 = gb_trees:insert(Addr, Term, D0), - D = gb_trees:insert(Binp, SymbolicBin, D1), + D = gb_trees:enter(Binp, SymbolicBin, D1), {Term,Line,D}; [] -> Term = '#CDVNonexistingBinary', D1 = gb_trees:insert(Addr, Term, D0), - D = gb_trees:insert(Binp, Term, D1), + D = gb_trees:enter(Binp, Term, D1), {Term,Line,D} end; parse_heap_term("Ys"++Line0, Addr, DecodeOpts, D0) -> %Sub binary. @@ -2887,12 +2882,17 @@ parse_heap_term("Ys"++Line0, Addr, DecodeOpts, D0) -> %Sub binary. {Term,Line,D}; parse_heap_term("Mf"++Line0, Addr, DecodeOpts, D0) -> %Flatmap. {Size,":"++Line1} = get_hex(Line0), - {Keys,":"++Line2,D1} = parse_term(Line1, DecodeOpts, D0), - {Values,Line,D2} = parse_tuple(Size, Line2, Addr,DecodeOpts, D1, []), - Pairs = zip_tuples(tuple_size(Keys), Keys, Values, []), - Map = maps:from_list(Pairs), - D = gb_trees:update(Addr, Map, D2), - {Map,Line,D}; + case parse_term(Line1, DecodeOpts, D0) of + {Keys,":"++Line2,D1} when is_tuple(Keys) -> + {Values,Line,D2} = parse_tuple(Size, Line2, Addr,DecodeOpts, D1, []), + Pairs = zip_tuples(tuple_size(Keys), Keys, Values, []), + Map = maps:from_list(Pairs), + D = gb_trees:update(Addr, Map, D2), + {Map,Line,D}; + {Incomplete,_Line,D1} -> + D = gb_trees:insert(Addr, Incomplete, D1), + {Incomplete,"",D} + end; parse_heap_term("Mh"++Line0, Addr, DecodeOpts, D0) -> %Head node in a hashmap. {MapSize,":"++Line1} = get_hex(Line0), {N,":"++Line2} = get_hex(Line1), @@ -3051,7 +3051,7 @@ do_deref_ptr(Lookup, Line, DecodeOpts, D0) -> {Term,Line,D0}; none -> put(incomplete_heap, true), - {['#CDVIncompleteHeap'],Line,D0}; + {'#CDVIncompleteHeap',Line,D0}; {line,Addr,NewLine} -> D = parse_line(Addr, NewLine, DecodeOpts, D0), do_deref_ptr(Lookup, Line, DecodeOpts, D) @@ -3275,13 +3275,13 @@ tag_to_atom(UnknownTag) -> %%%----------------------------------------------------------------- %%% Store last tag for use when truncated, and reason if aborted -put_last_tag(?abort,Reason) -> - %% Don't overwrite the real last tag, and make sure to return - %% the previous last tag. - put(truncated_reason,Reason), - get(last_tag); -put_last_tag(Tag,Id) -> - put(last_tag,{Tag,Id}). +put_last_tag(?abort,Reason,_Pos) -> + %% Don't overwrite the real last tag, and don't return it either, + %% since that would make the caller of this function believe that + %% the tag was complete. + put(truncated_reason,Reason); +put_last_tag(Tag,Id,Pos) -> + put(last_tag,{{Tag,Id},Pos}). %%%----------------------------------------------------------------- %%% Fetch next chunk from crashdump file diff --git a/lib/observer/test/crashdump_helper.erl b/lib/observer/test/crashdump_helper.erl index 576d112154..d5d3649525 100644 --- a/lib/observer/test/crashdump_helper.erl +++ b/lib/observer/test/crashdump_helper.erl @@ -64,6 +64,7 @@ n1_proc(Creator,_N2,Pid2,Port2,_L) -> put(ref,Ref), put(pid,Pid), put(bin,Bin), + put(proc_bins,create_proc_bins()), put(bins,create_binaries()), put(sub_bin,SubBin), put(sub_bins,create_sub_binaries(get(bins))), @@ -119,6 +120,23 @@ create_sub_binary(Bin, Start, LenSub) -> <<_:Start/bytes,Sub:Len/bytes,_/bytes>> = Bin, Sub. +create_proc_bins() -> + Parent = self(), + Pid = + spawn( + fun() -> + %% Just reverse the list here, so this binary is not + %% confused with the one created in n1_proc/5 above, + %% which is used for testing truncation (see + %% crashdump_viewer_SUITE:truncate_dump_binary/1) + Bin = list_to_binary(lists:reverse(lists:seq(1, 255))), + <<A:65/bytes,B:65/bytes,C/bytes>> = Bin, + Parent ! {self(),{A,B,C}} + end), + receive + {Pid,ProcBins} -> ProcBins + end. + %%% %%% Test dumping of maps. Dumping of maps only from OTP 20.2. %%% diff --git a/lib/observer/test/crashdump_viewer_SUITE.erl b/lib/observer/test/crashdump_viewer_SUITE.erl index ed53c46a0d..8c5e618f4a 100644 --- a/lib/observer/test/crashdump_viewer_SUITE.erl +++ b/lib/observer/test/crashdump_viewer_SUITE.erl @@ -400,6 +400,13 @@ special(File,Procs) -> crashdump_viewer:expand_binary({SOffset,SSize,SPos}), io:format(" expand binary ok",[]), + ProcBins = proplists:get_value(proc_bins,Dict), + {['#CDVBin',0,65,ProcBin], + ['#CDVBin',65,65,ProcBin], + ['#CDVBin',130,125,ProcBin]} = ProcBins, + io:format(" ProcBins ok",[]), + + Binaries = crashdump_helper:create_binaries(), verify_binaries(Binaries, proplists:get_value(bins,Dict)), io:format(" binaries ok",[]), diff --git a/lib/reltool/src/reltool_utils.erl b/lib/reltool/src/reltool_utils.erl index 060a0912f9..2afa386cb3 100644 --- a/lib/reltool/src/reltool_utils.erl +++ b/lib/reltool/src/reltool_utils.erl @@ -47,6 +47,9 @@ call/2, cast/2, reply/3]). +%% For testing +-export([erl_libs/2]). + -include_lib("kernel/include/file.hrl"). -include_lib("wx/include/wx.hrl"). -include("reltool.hrl"). @@ -55,7 +58,15 @@ root_dir() -> code:root_dir(). erl_libs() -> - string:lexemes(os:getenv("ERL_LIBS", ""), ":;"). + erl_libs(os:getenv("ERL_LIBS", ""), os:type()). + +erl_libs(ErlLibs, OsType) when is_list(ErlLibs) -> + Sep = + case OsType of + {win32, _} -> ";"; + _ -> ":" + end, + string:lexemes(ErlLibs, Sep). lib_dirs(Dir) -> case erl_prim_loader:list_dir(Dir) of diff --git a/lib/reltool/test/reltool_server_SUITE.erl b/lib/reltool/test/reltool_server_SUITE.erl index 4e1937d479..9ee61b595d 100644 --- a/lib/reltool/test/reltool_server_SUITE.erl +++ b/lib/reltool/test/reltool_server_SUITE.erl @@ -142,7 +142,8 @@ all() -> use_selected_vsn, use_selected_vsn_relative_path, non_standard_vsn_id, - undefined_regexp]. + undefined_regexp, + windows_erl_libs]. groups() -> []. @@ -2546,10 +2547,21 @@ undefined_regexp(_Config) -> ok. %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% +%% Checks that reltool_utils can correctly read Windows ERL_LIBS + +windows_erl_libs(_Config) -> + WinErlLibs = + "C:\\Program Files\\Erlang Libs;C:\\Program Files\\More Erlang Libs", + Ret = reltool_utils:erl_libs(WinErlLibs, {win32, nt}), + ?m(["C:\\Program Files\\Erlang Libs","C:\\Program Files\\More Erlang Libs"], + Ret), + ok. + +%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%% %% Library functions erl_libs() -> - string:lexemes(os:getenv("ERL_LIBS", ""), ":;"). + reltool_utils:erl_libs(). datadir(Config) -> %% Removes the trailing slash... diff --git a/lib/ssh/doc/src/ssh_file.xml b/lib/ssh/doc/src/ssh_file.xml index 47ed4dd912..6681d9c306 100644 --- a/lib/ssh/doc/src/ssh_file.xml +++ b/lib/ssh/doc/src/ssh_file.xml @@ -93,8 +93,8 @@ <item><marker id="SYSDIR-ssh_host_dsa_key"/><c>ssh_host_dsa_key</c> - private dss host key (optional)</item> <item><marker id="SYSDIR-ssh_host_rsa_key"/><c>ssh_host_rsa_key</c> - private rsa host key (optional)</item> <item><marker id="SYSDIR-ssh_host_ecdsa_key"/><c>ssh_host_ecdsa_key</c> - private ecdsa host key (optional)</item> - <item><marker id="SYSDIR-ssh_host_ed25519_key"/><c>ssh_host_ed25519_key</c> - private ecdsa host key for curve 25519 (optional)</item> - <item><marker id="SYSDIR-ssh_host_ed448_key"/><c>ssh_host_ed448_key</c> - private ecdsa host key for curve 448 (optional)</item> + <item><marker id="SYSDIR-ssh_host_ed25519_key"/><c>ssh_host_ed25519_key</c> - private eddsa host key for curve 25519 (optional)</item> + <item><marker id="SYSDIR-ssh_host_ed448_key"/><c>ssh_host_ed448_key</c> - private eddsa host key for curve 448 (optional)</item> </list> <p>At least one host key must be defined. The default value of SYSDIR is <marker id="#/etc/ssh"/><c>/etc/ssh</c>. </p> @@ -188,6 +188,8 @@ <item><seealso marker="#SYSDIR-ssh_host_rsa_key"><c>SYSDIR/ssh_host_rsa_key</c></seealso></item> <item><seealso marker="#SYSDIR-ssh_host_dsa_key"><c>SYSDIR/ssh_host_dsa_key</c></seealso></item> <item><seealso marker="#SYSDIR-ssh_host_ecdsa_key"><c>SYSDIR/ssh_host_ecdsa_key</c></seealso></item> + <item><seealso marker="#SYSDIR-ssh_host_ed25519_key"><c>SYSDIR/ssh_host_ed25519_key</c></seealso></item> + <item><seealso marker="#SYSDIR-ssh_host_ed448_key"><c>SYSDIR/ssh_host_ed448_key</c>c></seealso></item> </list> </desc> </func> diff --git a/lib/ssh/test/ssh_engine_SUITE.erl b/lib/ssh/test/ssh_engine_SUITE.erl index c2e6ac1fee..3adb23acdb 100644 --- a/lib/ssh/test/ssh_engine_SUITE.erl +++ b/lib/ssh/test/ssh_engine_SUITE.erl @@ -126,10 +126,17 @@ simple_connect(Config) -> load_engine() -> case crypto:get_test_engine() of {ok, Engine} -> - try crypto:engine_load(<<"dynamic">>, + try + %% The test engine has it's own fake rsa sign/verify that + %% you don't want to use, so exclude it from methods to load: + Methods = + crypto:engine_get_all_methods() -- [engine_method_rsa], + crypto:engine_load(<<"dynamic">>, [{<<"SO_PATH">>, Engine}, <<"LOAD">>], - []) + [], + Methods + ) catch error:notsup -> {error, notsup} diff --git a/lib/ssl/doc/src/ssl_app.xml b/lib/ssl/doc/src/ssl_app.xml index f6d9021d4a..893919aeb4 100644 --- a/lib/ssl/doc/src/ssl_app.xml +++ b/lib/ssl/doc/src/ssl_app.xml @@ -171,6 +171,20 @@ shutdown gracefully. Defaults to 5000 milliseconds. </p> </item> + + <tag><c><![CDATA[internal_active_n = integer() <optional>]]></c></tag> + <item> + <p> + For TLS connections this value is used to handle the + internal socket. As the implementation was changed from an + active once to an active N behavior (N = 100), for + performance reasons, this option exist for possible tweaking + or restoring of the old behavior (internal_active_n = 1) in + unforeseen scenarios. The option will not affect erlang + distribution over TLS that will always run in active N mode. + Added in ssl-9.1 (OTP-21.2). + </p> + </item> </taglist> </section> diff --git a/lib/ssl/src/dtls_connection.erl b/lib/ssl/src/dtls_connection.erl index 2a0b2b317d..37719ad439 100644 --- a/lib/ssl/src/dtls_connection.erl +++ b/lib/ssl/src/dtls_connection.erl @@ -39,7 +39,7 @@ -export([start_fsm/8, start_link/7, init/1, pids/1]). %% State transition handling --export([next_record/1, next_event/3, next_event/4, handle_common_event/4]). +-export([next_event/3, next_event/4, handle_common_event/4]). %% Handshake handling -export([renegotiate/2, send_handshake/2, @@ -50,7 +50,7 @@ -export([encode_alert/3, send_alert/2, send_alert_in_connection/2, close/5, protocol_name/0]). %% Data handling --export([encode_data/3, passive_receive/2, next_record_if_active/1, +-export([encode_data/3, next_record/1, send/3, socket/5, setopts/3, getopts/3]). %% gen_statem state functions @@ -162,9 +162,9 @@ next_record(State) -> next_event(StateName, Record, State) -> next_event(StateName, Record, State, []). -next_event(connection = StateName, no_record, +next_event(StateName, no_record, #state{connection_states = #{current_read := #{epoch := CurrentEpoch}}} = State0, Actions) -> - case next_record_if_active(State0) of + case next_record(State0) of {no_record, State} -> ssl_connection:hibernate_after(StateName, State, Actions); {#ssl_tls{epoch = CurrentEpoch, @@ -178,21 +178,18 @@ next_event(connection = StateName, no_record, {#ssl_tls{epoch = Epoch, type = ?HANDSHAKE, version = _Version}, State1} = _Record when Epoch == CurrentEpoch-1 -> - {State2, MoreActions} = send_handshake_flight(State1, CurrentEpoch), - {NextRecord, State} = next_record(State2), - next_event(StateName, NextRecord, State, Actions ++ MoreActions); + {State, MoreActions} = send_handshake_flight(State1, CurrentEpoch), + next_event(StateName, no_record, State, Actions ++ MoreActions); %% From FLIGHT perspective CHANGE_CIPHER_SPEC is treated as a handshake {#ssl_tls{epoch = Epoch, type = ?CHANGE_CIPHER_SPEC, version = _Version}, State1} = _Record when Epoch == CurrentEpoch-1 -> - {State2, MoreActions} = send_handshake_flight(State1, CurrentEpoch), - {NextRecord, State} = next_record(State2), - next_event(StateName, NextRecord, State, Actions ++ MoreActions); + {State, MoreActions} = send_handshake_flight(State1, CurrentEpoch), + next_event(StateName, no_record, State, Actions ++ MoreActions); {#ssl_tls{epoch = _Epoch, - version = _Version}, State1} -> + version = _Version}, State} -> %% TODO maybe buffer later epoch - {Record, State} = next_record(State1), - next_event(StateName, Record, State, Actions); + next_event(StateName, no_record, State, Actions); {#alert{} = Alert, State} -> {next_state, StateName, State, [{next_event, internal, Alert} | Actions]} end; @@ -210,24 +207,20 @@ next_event(connection = StateName, Record, #ssl_tls{epoch = Epoch, type = ?HANDSHAKE, version = _Version} when Epoch == CurrentEpoch-1 -> - {State1, MoreActions} = send_handshake_flight(State0, CurrentEpoch), - {NextRecord, State} = next_record(State1), - next_event(StateName, NextRecord, State, Actions ++ MoreActions); + {State, MoreActions} = send_handshake_flight(State0, CurrentEpoch), + next_event(StateName, no_record, State, Actions ++ MoreActions); %% From FLIGHT perspective CHANGE_CIPHER_SPEC is treated as a handshake #ssl_tls{epoch = Epoch, type = ?CHANGE_CIPHER_SPEC, version = _Version} when Epoch == CurrentEpoch-1 -> - {State1, MoreActions} = send_handshake_flight(State0, CurrentEpoch), - {NextRecord, State} = next_record(State1), - next_event(StateName, NextRecord, State, Actions ++ MoreActions); + {State, MoreActions} = send_handshake_flight(State0, CurrentEpoch), + next_event(StateName, no_record, State, Actions ++ MoreActions); _ -> next_event(StateName, no_record, State0, Actions) end; next_event(StateName, Record, #state{connection_states = #{current_read := #{epoch := CurrentEpoch}}} = State0, Actions) -> case Record of - no_record -> - {next_state, StateName, State0, Actions}; #ssl_tls{epoch = CurrentEpoch, version = Version} = Record -> State = dtls_version(StateName, Version, State0), @@ -236,8 +229,7 @@ next_event(StateName, Record, #ssl_tls{epoch = _Epoch, version = _Version} = _Record -> %% TODO maybe buffer later epoch - {Record, State} = next_record(State0), - next_event(StateName, Record, State, Actions); + next_event(StateName, no_record, State0, Actions); #alert{} = Alert -> {next_state, StateName, State0, [{next_event, internal, Alert} | Actions]} end. @@ -254,8 +246,7 @@ handle_common_event(internal, #ssl_tls{type = ?HANDSHAKE, try case dtls_handshake:get_dtls_handshake(Version, Data, Buffers0) of {[], Buffers} -> - {Record, State} = next_record(State0#state{protocol_buffers = Buffers}), - next_event(StateName, Record, State); + next_event(StateName, no_record, State0#state{protocol_buffers = Buffers}); {Packets, Buffers} -> State = State0#state{protocol_buffers = Buffers}, Events = dtls_handshake_events(Packets), @@ -291,15 +282,12 @@ handle_common_event(internal, #ssl_tls{type = _Unknown}, StateName, State) -> renegotiate(#state{role = client} = State, Actions) -> %% Handle same way as if server requested %% the renegotiation - {next_state, connection, State, - [{next_event, internal, #hello_request{}} | Actions]}; - + next_event(connection, no_record, State, [{next_event, internal, #hello_request{}} | Actions]); renegotiate(#state{role = server} = State0, Actions) -> HelloRequest = ssl_handshake:hello_request(), State1 = prepare_flight(State0), - {State2, MoreActions} = send_handshake(HelloRequest, State1), - {Record, State} = next_record(State2), - next_event(hello, Record, State, Actions ++ MoreActions). + {State, MoreActions} = send_handshake(HelloRequest, State1), + next_event(hello, no_record, State, Actions ++ MoreActions). send_handshake(Handshake, #state{connection_states = ConnectionStates} = State) -> #{epoch := Epoch} = ssl_record:current_connection_state(ConnectionStates, write), @@ -393,23 +381,6 @@ protocol_name() -> encode_data(Data, Version, ConnectionStates0)-> dtls_record:encode_data(Data, Version, ConnectionStates0). -passive_receive(State0 = #state{user_data_buffer = Buffer}, StateName) -> - case Buffer of - <<>> -> - {Record, State} = next_record(State0), - next_event(StateName, Record, State); - _ -> - {Record, State} = ssl_connection:read_application_data(<<>>, State0), - next_event(StateName, Record, State) - end. -next_record_if_active(State = - #state{socket_options = - #socket_options{active = false}}) -> - {no_record ,State}; - -next_record_if_active(State) -> - next_record(State). - send(Transport, {_, {{_,_}, _} = Socket}, Data) -> send(Transport, Socket, Data); send(Transport, Socket, Data) -> @@ -451,15 +422,14 @@ init({call, From}, {start, Timeout}, HelloVersion = dtls_record:hello_version(Version, SslOpts#ssl_options.versions), State1 = prepare_flight(State0#state{negotiated_version = Version}), {State2, Actions} = send_handshake(Hello, State1#state{negotiated_version = HelloVersion}), - State3 = State2#state{negotiated_version = Version, %% Requested version - session = - Session0#session{session_id = Hello#client_hello.session_id}, - start_or_recv_from = From, - timer = Timer, - flight_state = {retransmit, ?INITIAL_RETRANSMIT_TIMEOUT} - }, - {Record, State} = next_record(State3), - next_event(hello, Record, State, Actions); + State = State2#state{negotiated_version = Version, %% Requested version + session = + Session0#session{session_id = Hello#client_hello.session_id}, + start_or_recv_from = From, + timer = Timer, + flight_state = {retransmit, ?INITIAL_RETRANSMIT_TIMEOUT} + }, + next_event(hello, no_record, State, Actions); init({call, _} = Type, Event, #state{role = server, data_tag = udp} = State) -> Result = gen_handshake(?FUNCTION_NAME, Type, Event, State#state{flight_state = {retransmit, ?INITIAL_RETRANSMIT_TIMEOUT}, @@ -469,7 +439,6 @@ init({call, _} = Type, Event, #state{role = server, data_tag = udp} = State) -> max_ignored_alerts => 10}}), erlang:send_after(dtls_v1:cookie_timeout(), self(), new_cookie_secret), Result; - init({call, _} = Type, Event, #state{role = server} = State) -> %% I.E. DTLS over sctp gen_handshake(?FUNCTION_NAME, Type, Event, State#state{flight_state = reliable}); @@ -519,9 +488,9 @@ hello(internal, #client_hello{cookie = <<>>, %% negotiated. VerifyRequest = dtls_handshake:hello_verify_request(Cookie, ?HELLO_VERIFY_REQUEST_VERSION), State1 = prepare_flight(State0#state{negotiated_version = Version}), - {State2, Actions} = send_handshake(VerifyRequest, State1), - {Record, State} = next_record(State2), - next_event(?FUNCTION_NAME, Record, State#state{tls_handshake_history = ssl_handshake:init_handshake_history()}, Actions); + {State, Actions} = send_handshake(VerifyRequest, State1), + next_event(?FUNCTION_NAME, no_record, + State#state{tls_handshake_history = ssl_handshake:init_handshake_history()}, Actions); hello(internal, #hello_verify_request{cookie = Cookie}, #state{role = client, host = Host, port = Port, ssl_options = SslOpts, @@ -540,27 +509,29 @@ hello(internal, #hello_verify_request{cookie = Cookie}, #state{role = client, State1 = prepare_flight(State0#state{tls_handshake_history = ssl_handshake:init_handshake_history()}), {State2, Actions} = send_handshake(Hello, State1), - State3 = State2#state{negotiated_version = Version, %% Requested version - session = - Session0#session{session_id = - Hello#client_hello.session_id}}, - {Record, State} = next_record(State3), - next_event(?FUNCTION_NAME, Record, State, Actions); -hello(internal, #client_hello{extensions = Extensions} = Hello, #state{ssl_options = #ssl_options{handshake = hello}, - start_or_recv_from = From} = State) -> + State = State2#state{negotiated_version = Version, %% Requested version + session = + Session0#session{session_id = + Hello#client_hello.session_id}}, + next_event(?FUNCTION_NAME, no_record, State, Actions); +hello(internal, #client_hello{extensions = Extensions} = Hello, + #state{ssl_options = #ssl_options{handshake = hello}, + start_or_recv_from = From} = State) -> {next_state, user_hello, State#state{start_or_recv_from = undefined, hello = Hello}, [{reply, From, {ok, ssl_connection:map_extensions(Extensions)}}]}; -hello(internal, #server_hello{extensions = Extensions} = Hello, #state{ssl_options = #ssl_options{handshake = hello}, - start_or_recv_from = From} = State) -> +hello(internal, #server_hello{extensions = Extensions} = Hello, + #state{ssl_options = #ssl_options{handshake = hello}, + start_or_recv_from = From} = State) -> {next_state, user_hello, State#state{start_or_recv_from = undefined, hello = Hello}, [{reply, From, {ok, ssl_connection:map_extensions(Extensions)}}]}; -hello(internal, #client_hello{cookie = Cookie} = Hello, #state{role = server, - transport_cb = Transport, - socket = Socket, - protocol_specific = #{current_cookie_secret := Secret, - previous_cookie_secret := PSecret}} = State0) -> +hello(internal, #client_hello{cookie = Cookie} = Hello, + #state{role = server, + transport_cb = Transport, + socket = Socket, + protocol_specific = #{current_cookie_secret := Secret, + previous_cookie_secret := PSecret}} = State0) -> {ok, {IP, Port}} = dtls_socket:peername(Transport, Socket), case dtls_handshake:cookie(Secret, IP, Port, Hello) of Cookie -> @@ -595,8 +566,7 @@ hello(internal, {handshake, {#hello_verify_request{} = Handshake, _}}, State) -> {next_state, ?FUNCTION_NAME, State, [{next_event, internal, Handshake}]}; hello(internal, #change_cipher_spec{type = <<1>>}, State0) -> {State1, Actions0} = send_handshake_flight(State0, retransmit_epoch(?FUNCTION_NAME, State0)), - {Record, State2} = next_record(State1), - {next_state, ?FUNCTION_NAME, State, Actions} = next_event(?FUNCTION_NAME, Record, State2, Actions0), + {next_state, ?FUNCTION_NAME, State, Actions} = next_event(?FUNCTION_NAME, no_record, State1, Actions0), %% This will reset the retransmission timer by repeating the enter state event {repeat_state, State, Actions}; hello(info, Event, State) -> @@ -647,8 +617,7 @@ certify(internal = Type, #server_hello_done{} = Event, State) -> ssl_connection:certify(Type, Event, prepare_flight(State), ?MODULE); certify(internal, #change_cipher_spec{type = <<1>>}, State0) -> {State1, Actions0} = send_handshake_flight(State0, retransmit_epoch(?FUNCTION_NAME, State0)), - {Record, State2} = next_record(State1), - {next_state, ?FUNCTION_NAME, State, Actions} = next_event(?FUNCTION_NAME, Record, State2, Actions0), + {next_state, ?FUNCTION_NAME, State, Actions} = next_event(?FUNCTION_NAME, no_record, State1, Actions0), %% This will reset the retransmission timer by repeating the enter state event {repeat_state, State, Actions}; certify(state_timeout, Event, State) -> @@ -701,13 +670,11 @@ connection(internal, #hello_request{}, #state{host = Host, port = Port, Version = Hello#client_hello.client_version, HelloVersion = dtls_record:hello_version(Version, SslOpts#ssl_options.versions), State1 = prepare_flight(State0), - {State2, Actions} = send_handshake(Hello, State1#state{negotiated_version = HelloVersion}), - {Record, State} = - next_record( - State2#state{flight_state = {retransmit, ?INITIAL_RETRANSMIT_TIMEOUT}, - session = Session0#session{session_id - = Hello#client_hello.session_id}}), - next_event(hello, Record, State, Actions); + {State, Actions} = send_handshake(Hello, State1#state{negotiated_version = HelloVersion}), + next_event(hello, no_record, State#state{flight_state = {retransmit, ?INITIAL_RETRANSMIT_TIMEOUT}, + session = Session0#session{session_id + = Hello#client_hello.session_id}}, + Actions); connection(internal, #client_hello{} = Hello, #state{role = server, allow_renegotiate = true} = State) -> %% Mitigate Computational DoS attack %% http://www.educatedguesswork.org/2011/10/ssltls_and_computational_dos.html @@ -927,8 +894,7 @@ handle_state_timeout(flight_retransmission_timeout, StateName, #state{flight_state = {retransmit, NextTimeout}} = State0) -> {State1, Actions0} = send_handshake_flight(State0#state{flight_state = {retransmit, NextTimeout}}, retransmit_epoch(StateName, State0)), - {Record, State2} = next_record(State1), - {next_state, StateName, State, Actions} = next_event(StateName, Record, State2, Actions0), + {next_state, StateName, State, Actions} = next_event(StateName, no_record, State1, Actions0), %% This will reset the retransmission timer by repeating the enter state event {repeat_state, State, Actions}. diff --git a/lib/ssl/src/ssl_connection.erl b/lib/ssl/src/ssl_connection.erl index 9b16c3c9ed..4b406b4c1e 100644 --- a/lib/ssl/src/ssl_connection.erl +++ b/lib/ssl/src/ssl_connection.erl @@ -403,9 +403,8 @@ handle_alert(#alert{level = ?WARNING, description = ?NO_RENEGOTIATION} = Alert, log_alert(SslOpts#ssl_options.log_alert, Role, Connection:protocol_name(), StateName, Alert#alert{role = opposite_role(Role)}), gen_statem:reply(From, {error, renegotiation_rejected}), - State1 = Connection:reinit_handshake_data(State0), - {Record, State} = Connection:next_record(State1#state{renegotiation = undefined}), - Connection:next_event(connection, Record, State); + State = Connection:reinit_handshake_data(State0), + Connection:next_event(connection, no_record, State#state{renegotiation = undefined}); handle_alert(#alert{level = ?WARNING, description = ?NO_RENEGOTIATION} = Alert, StateName, #state{role = Role, @@ -414,22 +413,35 @@ handle_alert(#alert{level = ?WARNING, description = ?NO_RENEGOTIATION} = Alert, log_alert(SslOpts#ssl_options.log_alert, Role, Connection:protocol_name(), StateName, Alert#alert{role = opposite_role(Role)}), gen_statem:reply(From, {error, renegotiation_rejected}), - {Record, State1} = Connection:next_record(State0), %% Go back to connection! - State = Connection:reinit(State1#state{renegotiation = undefined}), - Connection:next_event(connection, Record, State); + State = Connection:reinit(State0#state{renegotiation = undefined}), + Connection:next_event(connection, no_record, State); %% Gracefully log and ignore all other warning alerts handle_alert(#alert{level = ?WARNING} = Alert, StateName, - #state{ssl_options = SslOpts, protocol_cb = Connection, role = Role} = State0) -> + #state{ssl_options = SslOpts, protocol_cb = Connection, role = Role} = State) -> log_alert(SslOpts#ssl_options.log_alert, Role, Connection:protocol_name(), StateName, Alert#alert{role = opposite_role(Role)}), - {Record, State} = Connection:next_record(State0), - Connection:next_event(StateName, Record, State). + Connection:next_event(StateName, no_record, State). %%==================================================================== %% Data handling %%==================================================================== + +passive_receive(State0 = #state{user_data_buffer = Buffer}, StateName, Connection) -> + case Buffer of + <<>> -> + {Record, State} = Connection:next_record(State0), + Connection:next_event(StateName, Record, State); + _ -> + case read_application_data(<<>>, State0) of + {stop, _, _} = ShutdownError -> + ShutdownError; + {Record, State} -> + Connection:next_event(StateName, Record, State) + end + end. + read_application_data(Data, #state{user_application = {_Mon, Pid}, socket = Socket, protocol_cb = Connection, @@ -472,28 +484,26 @@ read_application_data(Data, #state{user_application = {_Mon, Pid}, Buffer =:= <<>> -> %% Passive mode, wait for active once or recv %% Active and empty, get more data - Connection:next_record_if_active(State); + {no_record, State}; true -> %% We have more data read_application_data(<<>>, State) end end; {more, Buffer} -> % no reply, we need more data - Connection:next_record(State0#state{user_data_buffer = Buffer}); + {no_record, State0#state{user_data_buffer = Buffer}}; {passive, Buffer} -> - Connection:next_record_if_active(State0#state{user_data_buffer = Buffer}); + {no_record, State0#state{user_data_buffer = Buffer}}; {error,_Reason} -> %% Invalid packet in packet mode deliver_packet_error(Connection:pids(State0), Transport, Socket, SOpts, Buffer1, Pid, RecvFrom, Tracker, Connection), stop(normal, State0) end. -dist_app_data(ClientData, #state{protocol_cb = Connection, - erl_dist_data = #{dist_handle := undefined, +dist_app_data(ClientData, #state{erl_dist_data = #{dist_handle := undefined, dist_buffer := DistBuff} = DistData} = State) -> - Connection:next_record_if_active(State#state{erl_dist_data = DistData#{dist_buffer => [ClientData, DistBuff]}}); + {no_record, State#state{erl_dist_data = DistData#{dist_buffer => [ClientData, DistBuff]}}}; dist_app_data(ClientData, #state{erl_dist_data = #{dist_handle := DHandle, dist_buffer := DistBuff} = ErlDistData, - protocol_cb = Connection, user_data_buffer = Buffer, socket_options = SOpts} = State) -> Data = merge_dist_data(DistBuff, ClientData), @@ -502,7 +512,7 @@ dist_app_data(ClientData, #state{erl_dist_data = #{dist_handle := DHandle, Buffer =:= <<>> -> %% Passive mode, wait for active once or recv %% Active and empty, get more data - Connection:next_record_if_active(State#state{erl_dist_data = ErlDistData#{dist_buffer => <<>>}}); + {no_record, State#state{erl_dist_data = ErlDistData#{dist_buffer => <<>>}}}; _ -> %% We have more data read_application_data(<<>>, State) catch error:_ -> @@ -606,9 +616,7 @@ ssl_config(Opts, Role, State0, Type) -> init({call, From}, {start, Timeout}, State0, Connection) -> Timer = start_or_recv_cancel_timer(Timeout, From), - {Record, State} = Connection:next_record(State0#state{start_or_recv_from = From, - timer = Timer}), - Connection:next_event(hello, Record, State); + Connection:next_event(hello, no_record, State0#state{start_or_recv_from = From, timer = Timer}); init({call, From}, {start, {Opts, EmOpts}, Timeout}, #state{role = Role, ssl_options = OrigSSLOptions, socket_options = SockOpts} = State0, Connection) -> @@ -721,20 +729,19 @@ abbreviated(internal, #finished{verify_data = Data} = Finished, %% only allowed to send next_protocol message after change cipher spec %% & before finished message and it is not allowed during renegotiation abbreviated(internal, #next_protocol{selected_protocol = SelectedProtocol}, - #state{role = server, expecting_next_protocol_negotiation = true} = State0, + #state{role = server, expecting_next_protocol_negotiation = true} = State, Connection) -> - {Record, State} = - Connection:next_record(State0#state{negotiated_protocol = SelectedProtocol}), - Connection:next_event(?FUNCTION_NAME, Record, - State#state{expecting_next_protocol_negotiation = false}); + Connection:next_event(?FUNCTION_NAME, no_record, + State#state{negotiated_protocol = SelectedProtocol, + expecting_next_protocol_negotiation = false}); abbreviated(internal, #change_cipher_spec{type = <<1>>}, - #state{connection_states = ConnectionStates0} = State0, Connection) -> + #state{connection_states = ConnectionStates0} = State, Connection) -> ConnectionStates1 = ssl_record:activate_pending_connection_state(ConnectionStates0, read, Connection), - {Record, State} = Connection:next_record(State0#state{connection_states = - ConnectionStates1}), - Connection:next_event(?FUNCTION_NAME, Record, State#state{expecting_finished = true}); + Connection:next_event(?FUNCTION_NAME, no_record, State#state{connection_states = + ConnectionStates1, + expecting_finished = true}); abbreviated(info, Msg, State, _) -> handle_info(Msg, ?FUNCTION_NAME, State); abbreviated(Type, Msg, State, Connection) -> @@ -763,9 +770,7 @@ certify(internal, #certificate{asn1_certificates = []}, ssl_options = #ssl_options{verify = verify_peer, fail_if_no_peer_cert = false}} = State0, Connection) -> - {Record, State} = - Connection:next_record(State0#state{client_certificate_requested = false}), - Connection:next_event(?FUNCTION_NAME, Record, State); + Connection:next_event(?FUNCTION_NAME, no_record, State0#state{client_certificate_requested = false}); certify(internal, #certificate{}, #state{role = server, negotiated_version = Version, @@ -833,24 +838,23 @@ certify(internal, #certificate_request{}, Version, ?FUNCTION_NAME, State); certify(internal, #certificate_request{}, #state{session = #session{own_certificate = undefined}, - role = client} = State0, Connection) -> + role = client} = State, Connection) -> %% The client does not have a certificate and will send an empty reply, the server may fail %% or accept the connection by its own preference. No signature algorihms needed as there is %% no certificate to verify. - {Record, State} = Connection:next_record(State0), - Connection:next_event(?FUNCTION_NAME, Record, State#state{client_certificate_requested = true}); + Connection:next_event(?FUNCTION_NAME, no_record, State#state{client_certificate_requested = true}); certify(internal, #certificate_request{} = CertRequest, #state{session = #session{own_certificate = Cert}, role = client, ssl_options = #ssl_options{signature_algs = SupportedHashSigns}, - negotiated_version = Version} = State0, Connection) -> + negotiated_version = Version} = State, Connection) -> case ssl_handshake:select_hashsign(CertRequest, Cert, SupportedHashSigns, ssl:tls_version(Version)) of #alert {} = Alert -> - handle_own_alert(Alert, Version, ?FUNCTION_NAME, State0); - NegotiatedHashSign -> - {Record, State} = Connection:next_record(State0#state{client_certificate_requested = true}), - Connection:next_event(?FUNCTION_NAME, Record, - State#state{cert_hashsign_algorithm = NegotiatedHashSign}) + handle_own_alert(Alert, Version, ?FUNCTION_NAME, State); + NegotiatedHashSign -> + Connection:next_event(?FUNCTION_NAME, no_record, + State#state{client_certificate_requested = true, + cert_hashsign_algorithm = NegotiatedHashSign}) end; %% PSK and RSA_PSK might bypass the Server-Key-Exchange certify(internal, #server_hello_done{}, @@ -959,7 +963,7 @@ cipher(internal, #certificate_verify{signature = Signature, negotiated_version = Version, session = #session{master_secret = MasterSecret}, tls_handshake_history = Handshake - } = State0, Connection) -> + } = State, Connection) -> TLSVersion = ssl:tls_version(Version), %% Use negotiated value if TLS-1.2 otherwhise return default @@ -967,11 +971,10 @@ cipher(internal, #certificate_verify{signature = Signature, case ssl_handshake:certificate_verify(Signature, PublicKeyInfo, TLSVersion, HashSign, MasterSecret, Handshake) of valid -> - {Record, State} = Connection:next_record(State0), - Connection:next_event(?FUNCTION_NAME, Record, + Connection:next_event(?FUNCTION_NAME, no_record, State#state{cert_hashsign_algorithm = HashSign}); #alert{} = Alert -> - handle_own_alert(Alert, Version, ?FUNCTION_NAME, State0) + handle_own_alert(Alert, Version, ?FUNCTION_NAME, State) end; %% client must send a next protocol message if we are expecting it cipher(internal, #finished{}, @@ -1005,18 +1008,18 @@ cipher(internal, #finished{verify_data = Data} = Finished, %% & before finished message and it is not allowed during renegotiation cipher(internal, #next_protocol{selected_protocol = SelectedProtocol}, #state{role = server, expecting_next_protocol_negotiation = true, - expecting_finished = true} = State0, Connection) -> - {Record, State} = - Connection:next_record(State0#state{negotiated_protocol = SelectedProtocol}), - Connection:next_event(?FUNCTION_NAME, Record, - State#state{expecting_next_protocol_negotiation = false}); + expecting_finished = true} = State, Connection) -> + Connection:next_event(?FUNCTION_NAME, no_record, + State#state{expecting_next_protocol_negotiation = false, + negotiated_protocol = SelectedProtocol + }); cipher(internal, #change_cipher_spec{type = <<1>>}, #state{connection_states = ConnectionStates0} = - State0, Connection) -> - ConnectionStates1 = + State, Connection) -> + ConnectionStates = ssl_record:activate_pending_connection_state(ConnectionStates0, read, Connection), - {Record, State} = Connection:next_record(State0#state{connection_states = - ConnectionStates1}), - Connection:next_event(?FUNCTION_NAME, Record, State#state{expecting_finished = true}); + Connection:next_event(?FUNCTION_NAME, no_record, State#state{connection_states = + ConnectionStates, + expecting_finished = true}); cipher(Type, Msg, State, Connection) -> handle_common_event(Type, Msg, ?FUNCTION_NAME, State, Connection). @@ -1029,9 +1032,9 @@ connection({call, RecvFrom}, {recv, N, Timeout}, #state{protocol_cb = Connection, socket_options = #socket_options{active = false}} = State0, Connection) -> Timer = start_or_recv_cancel_timer(Timeout, RecvFrom), - Connection:passive_receive(State0#state{bytes_to_read = N, - start_or_recv_from = RecvFrom, - timer = Timer}, ?FUNCTION_NAME); + passive_receive(State0#state{bytes_to_read = N, + start_or_recv_from = RecvFrom, + timer = Timer}, ?FUNCTION_NAME, Connection); connection({call, From}, renegotiate, #state{protocol_cb = Connection} = State, Connection) -> Connection:renegotiate(State#state{renegotiation = {true, From}}, []); @@ -1073,7 +1076,7 @@ connection(cast, {dist_handshake_complete, DHandle}, connection(info, Msg, State, _) -> handle_info(Msg, ?FUNCTION_NAME, State); connection(internal, {recv, _}, State, Connection) -> - Connection:passive_receive(State, ?FUNCTION_NAME); + passive_receive(State, ?FUNCTION_NAME, Connection); connection(Type, Msg, State, Connection) -> handle_common_event(Type, Msg, ?FUNCTION_NAME, State, Connection). @@ -1132,15 +1135,15 @@ handle_common_event(internal, {application_data, Data}, StateName, State0, Conne case read_application_data(Data, State0) of {stop, _, _} = Stop-> Stop; - {Record, State} -> - case Connection:next_event(StateName, Record, State) of - {next_state, StateName, State} -> - hibernate_after(StateName, State, []); - {next_state, StateName, State, Actions} -> - hibernate_after(StateName, State, Actions); - {stop, _, _} = Stop -> - Stop - end + {Record, State1} -> + case Connection:next_event(StateName, Record, State1) of + {next_state, StateName, State} -> + hibernate_after(StateName, State, []); + {next_state, StateName, State, Actions} -> + hibernate_after(StateName, State, Actions); + {stop, _, _} = Stop -> + Stop + end end; handle_common_event(internal, #change_cipher_spec{type = <<1>>}, StateName, #state{negotiated_version = Version} = State, _) -> @@ -1170,23 +1173,31 @@ handle_call({close, _} = Close, From, StateName, State, _Connection) -> stop_and_reply( {shutdown, normal}, {reply, From, Result}, State#state{terminated = true}); -handle_call({shutdown, How0}, From, StateName, +handle_call({shutdown, read_write = How}, From, StateName, #state{transport_cb = Transport, socket = Socket} = State, _) -> - case How0 of - How when How == write; How == both -> - send_alert(?ALERT_REC(?WARNING, ?CLOSE_NOTIFY), - StateName, State); - _ -> - ok - end, + try send_alert(?ALERT_REC(?WARNING, ?CLOSE_NOTIFY), + StateName, State) of + _ -> + case Transport:shutdown(Socket, How) of + ok -> + {next_state, StateName, State#state{terminated = true}, [{reply, From, ok}]}; + Error -> + {stop, StateName, State#state{terminated = true}, [{reply, From, Error}]} + end + catch + throw:Return -> + Return + end; +handle_call({shutdown, How0}, From, StateName, + #state{transport_cb = Transport, + socket = Socket} = State, _) -> case Transport:shutdown(Socket, How0) of ok -> - {keep_state_and_data, [{reply, From, ok}]}; + {next_state, StateName, State, [{reply, From, ok}]}; Error -> - gen_statem:reply(From, {error, Error}), - stop(normal, State) + {stop, StateName, State, [{reply, From, Error}]} end; handle_call({recv, _N, _Timeout}, From, _, #state{socket_options = @@ -1348,15 +1359,15 @@ terminate(downgrade = Reason, connection, #state{protocol_cb = Connection, handle_trusted_certs_db(State), Connection:close(Reason, Socket, Transport, undefined, undefined); terminate(Reason, connection, #state{protocol_cb = Connection, - connection_states = ConnectionStates, - ssl_options = #ssl_options{padding_check = Check}, - transport_cb = Transport, socket = Socket - } = State) -> + connection_states = ConnectionStates, + ssl_options = #ssl_options{padding_check = Check}, + transport_cb = Transport, socket = Socket + } = State) -> handle_trusted_certs_db(State), Alert = terminate_alert(Reason), %% Send the termination ALERT if possible - catch (ok = Connection:send_alert_in_connection(Alert, State)), - Connection:close(Reason, Socket, Transport, ConnectionStates, Check); + catch (Connection:send_alert_in_connection(Alert, State)), + Connection:close({timeout, ?DEFAULT_TIMEOUT}, Socket, Transport, ConnectionStates, Check); terminate(Reason, _StateName, #state{transport_cb = Transport, protocol_cb = Connection, socket = Socket } = State) -> @@ -1453,13 +1464,12 @@ new_server_hello(#server_hello{cipher_suite = CipherSuite, negotiated_version = Version} = State0, Connection) -> try server_certify_and_key_exchange(State0, Connection) of #state{} = State1 -> - {State2, Actions} = server_hello_done(State1, Connection), + {State, Actions} = server_hello_done(State1, Connection), Session = Session0#session{session_id = SessionId, cipher_suite = CipherSuite, compression_method = Compression}, - {Record, State} = Connection:next_record(State2#state{session = Session}), - Connection:next_event(certify, Record, State, Actions) + Connection:next_event(certify, no_record, State#state{session = Session}, Actions) catch #alert{} = Alert -> handle_own_alert(Alert, Version, hello, State0) @@ -1474,10 +1484,9 @@ resumed_server_hello(#state{session = Session, {_, ConnectionStates1} -> State1 = State0#state{connection_states = ConnectionStates1, session = Session}, - {State2, Actions} = + {State, Actions} = finalize_handshake(State1, abbreviated, Connection), - {Record, State} = Connection:next_record(State2), - Connection:next_event(abbreviated, Record, State, Actions); + Connection:next_event(abbreviated, no_record, State, Actions); #alert{} = Alert -> handle_own_alert(Alert, Version, hello, State0) end. @@ -1499,10 +1508,8 @@ handle_peer_cert(Role, PeerCert, PublicKeyInfo, Session#session{peer_certificate = PeerCert}, public_key_info = PublicKeyInfo}, #{key_exchange := KeyAlgorithm} = ssl_cipher_format:suite_definition(CipherSuite), - State2 = handle_peer_cert_key(Role, PeerCert, PublicKeyInfo, KeyAlgorithm, State1), - - {Record, State} = Connection:next_record(State2), - Connection:next_event(certify, Record, State). + State = handle_peer_cert_key(Role, PeerCert, PublicKeyInfo, KeyAlgorithm, State1), + Connection:next_event(certify, no_record, State). handle_peer_cert_key(client, _, {?'id-ecPublicKey', #'ECPoint'{point = _ECPoint} = PublicKey, @@ -1560,11 +1567,10 @@ client_certify_and_key_exchange(#state{negotiated_version = Version} = try do_client_certify_and_key_exchange(State0, Connection) of State1 = #state{} -> {State2, Actions} = finalize_handshake(State1, certify, Connection), - State3 = State2#state{ - %% Reinitialize - client_certificate_requested = false}, - {Record, State} = Connection:next_record(State3), - Connection:next_event(cipher, Record, State, Actions) + State = State2#state{ + %% Reinitialize + client_certificate_requested = false}, + Connection:next_event(cipher, no_record, State, Actions) catch throw:#alert{} = Alert -> handle_own_alert(Alert, Version, certify, State0) @@ -1973,10 +1979,9 @@ calculate_master_secret(PremasterSecret, ConnectionStates0, server) of {MasterSecret, ConnectionStates} -> Session = Session0#session{master_secret = MasterSecret}, - State1 = State0#state{connection_states = ConnectionStates, + State = State0#state{connection_states = ConnectionStates, session = Session}, - {Record, State} = Connection:next_record(State1), - Connection:next_event(Next, Record, State); + Connection:next_event(Next, no_record, State); #alert{} = Alert -> handle_own_alert(Alert, Version, certify, State0) end. @@ -2049,10 +2054,9 @@ calculate_secret(#server_ecdh_params{curve = ECCurve, public = ECServerPubKey}, calculate_secret(#server_psk_params{ hint = IdentityHint}, - State0, Connection) -> + State, Connection) -> %% store for later use - {Record, State} = Connection:next_record(State0#state{psk_identity = IdentityHint}), - Connection:next_event(certify, Record, State); + Connection:next_event(certify, no_record, State#state{psk_identity = IdentityHint}); calculate_secret(#server_dhe_psk_params{ dh_params = #server_dh_params{dh_p = Prime, dh_g = Base}} = ServerKey, @@ -2345,9 +2349,8 @@ prepare_connection(#state{renegotiation = Renegotiate, start_or_recv_from = RecvFrom} = State0, Connection) when Renegotiate =/= {false, first}, RecvFrom =/= undefined -> - State1 = Connection:reinit(State0), - {Record, State} = Connection:next_record(State1), - {Record, ack_connection(State)}; + State = Connection:reinit(State0), + {no_record, ack_connection(State)}; prepare_connection(State0, Connection) -> State = Connection:reinit(State0), {no_record, ack_connection(State)}. @@ -2401,26 +2404,23 @@ handle_new_session(NewId, CipherSuite, Compression, Session = Session0#session{session_id = NewId, cipher_suite = CipherSuite, compression_method = Compression}, - {Record, State} = Connection:next_record(State0#state{session = Session}), - Connection:next_event(certify, Record, State). + Connection:next_event(certify, no_record, State0#state{session = Session}). handle_resumed_session(SessId, #state{connection_states = ConnectionStates0, negotiated_version = Version, host = Host, port = Port, protocol_cb = Connection, session_cache = Cache, - session_cache_cb = CacheCb} = State0) -> + session_cache_cb = CacheCb} = State) -> Session = CacheCb:lookup(Cache, {{Host, Port}, SessId}), case ssl_handshake:master_secret(ssl:tls_version(Version), Session, ConnectionStates0, client) of {_, ConnectionStates} -> - {Record, State} = - Connection:next_record(State0#state{ - connection_states = ConnectionStates, - session = Session}), - Connection:next_event(abbreviated, Record, State); + Connection:next_event(abbreviated, no_record, State#state{ + connection_states = ConnectionStates, + session = Session}); #alert{} = Alert -> - handle_own_alert(Alert, Version, hello, State0) + handle_own_alert(Alert, Version, hello, State) end. make_premaster_secret({MajVer, MinVer}, rsa) -> @@ -2470,10 +2470,7 @@ handle_active_option(false, connection = StateName, To, Reply, State) -> handle_active_option(_, connection = StateName0, To, Reply, #state{protocol_cb = Connection, user_data_buffer = <<>>} = State0) -> - %% Need data, set active once - {Record, State1} = Connection:next_record_if_active(State0), - %% Note: Renogotiation may cause StateName0 =/= StateName - case Connection:next_event(StateName0, Record, State1) of + case Connection:next_event(StateName0, no_record, State0) of {next_state, StateName, State} -> hibernate_after(StateName, State, [{reply, To, Reply}]); {next_state, StateName, State, Actions} -> diff --git a/lib/ssl/src/ssl_internal.hrl b/lib/ssl/src/ssl_internal.hrl index fd246e2550..63e751440a 100644 --- a/lib/ssl/src/ssl_internal.hrl +++ b/lib/ssl/src/ssl_internal.hrl @@ -60,6 +60,7 @@ -define(CDR_MAGIC, "GIOP"). -define(CDR_HDR_SIZE, 12). +-define(INTERNAL_ACTIVE_N, 100). -define(DEFAULT_TIMEOUT, 5000). -define(NO_DIST_POINT, "http://dummy/no_distribution_point"). diff --git a/lib/ssl/src/tls_connection.erl b/lib/ssl/src/tls_connection.erl index 87e7809817..0f986b5e21 100644 --- a/lib/ssl/src/tls_connection.erl +++ b/lib/ssl/src/tls_connection.erl @@ -46,7 +46,7 @@ -export([start_fsm/8, start_link/8, init/1, pids/1]). %% State transition handling --export([next_record/1, next_event/3, next_event/4, +-export([next_event/3, next_event/4, handle_common_event/4]). %% Handshake handling @@ -61,7 +61,7 @@ encode_alert/3, close/5, protocol_name/0]). %% Data handling --export([encode_data/3, passive_receive/2, next_record_if_active/1, +-export([encode_data/3, next_record/1, send/3, socket/5, setopts/3, getopts/3]). %% gen_statem state functions @@ -161,30 +161,30 @@ next_record(#state{protocol_buffers = {Alert, State} end; next_record(#state{protocol_buffers = #protocol_buffers{tls_packets = [], tls_cipher_texts = []}, - socket = Socket, + protocol_specific = #{active_n_toggle := true, active_n := N} = ProtocolSpec, + socket = Socket, close_tag = CloseTag, transport_cb = Transport} = State) -> - case tls_socket:setopts(Transport, Socket, [{active,once}]) of - ok -> - {no_record, State}; - _ -> - self() ! {CloseTag, Socket}, - {no_record, State} - end; + case tls_socket:setopts(Transport, Socket, [{active, N}]) of + ok -> + {no_record, State#state{protocol_specific = ProtocolSpec#{active_n_toggle => false}}}; + _ -> + self() ! {CloseTag, Socket}, + {no_record, State} + end; next_record(State) -> {no_record, State}. next_event(StateName, Record, State) -> next_event(StateName, Record, State, []). - -next_event(connection = StateName, no_record, State0, Actions) -> - case next_record_if_active(State0) of - {no_record, State} -> - ssl_connection:hibernate_after(StateName, State, Actions); - {#ssl_tls{} = Record, State} -> - {next_state, StateName, State, [{next_event, internal, {protocol_record, Record}} | Actions]}; - {#alert{} = Alert, State} -> - {next_state, StateName, State, [{next_event, internal, Alert} | Actions]} +next_event(StateName, no_record, State0, Actions) -> + case next_record(State0) of + {no_record, State} -> + {next_state, StateName, State, Actions}; + {#ssl_tls{} = Record, State} -> + {next_state, StateName, State, [{next_event, internal, {protocol_record, Record}} | Actions]}; + {#alert{} = Alert, State} -> + {next_state, StateName, State, [{next_event, internal, Alert} | Actions]} end; next_event(StateName, Record, State, Actions) -> case Record of @@ -207,22 +207,21 @@ handle_common_event(internal, #ssl_tls{type = ?HANDSHAKE, fragment = Data}, ssl_options = Options} = State0) -> try {Packets, Buf} = tls_handshake:get_tls_handshake(Version,Data,Buf0, Options), - State1 = + State = State0#state{protocol_buffers = Buffers#protocol_buffers{tls_handshake_buffer = Buf}}, case Packets of [] -> assert_buffer_sanity(Buf, Options), - {Record, State} = next_record(State1), - next_event(StateName, Record, State); + next_event(StateName, no_record, State); _ -> Events = tls_handshake_events(Packets), case StateName of connection -> - ssl_connection:hibernate_after(StateName, State1, Events); + ssl_connection:hibernate_after(StateName, State, Events); _ -> {next_state, StateName, - State1#state{unprocessed_handshake_events = unprocessed_events(Events)}, Events} + State#state{unprocessed_handshake_events = unprocessed_events(Events)}, Events} end end catch throw:#alert{} = Alert -> @@ -277,11 +276,10 @@ renegotiate(#state{role = server, {BinMsg, ConnectionStates} = tls_record:encode_handshake(Frag, Version, ConnectionStates0), send(Transport, Socket, BinMsg), - State1 = State0#state{connection_states = + State = State0#state{connection_states = ConnectionStates, tls_handshake_history = Hs0}, - {Record, State} = next_record(State1), - next_event(hello, Record, State, Actions). + next_event(hello, no_record, State, Actions). send_handshake(Handshake, State) -> send_handshake_flight(queue_handshake(Handshake, State)). @@ -409,23 +407,6 @@ protocol_name() -> encode_data(Data, Version, ConnectionStates0)-> tls_record:encode_data(Data, Version, ConnectionStates0). -passive_receive(State0 = #state{user_data_buffer = Buffer}, StateName) -> - case Buffer of - <<>> -> - {Record, State} = next_record(State0), - next_event(StateName, Record, State); - _ -> - {Record, State} = ssl_connection:read_application_data(<<>>, State0), - next_event(StateName, Record, State) - end. - -next_record_if_active(State = - #state{socket_options = - #socket_options{active = false}}) -> - {no_record ,State}; -next_record_if_active(State) -> - next_record(State). - send(Transport, Socket, Data) -> tls_socket:send(Transport, Socket, Data). @@ -467,15 +448,14 @@ init({call, From}, {start, Timeout}, {BinMsg, ConnectionStates, Handshake} = encode_handshake(Hello, HelloVersion, ConnectionStates0, Handshake0), send(Transport, Socket, BinMsg), - State1 = State0#state{connection_states = ConnectionStates, - negotiated_version = Version, %% Requested version - session = - Session0#session{session_id = Hello#client_hello.session_id}, - tls_handshake_history = Handshake, - start_or_recv_from = From, + State = State0#state{connection_states = ConnectionStates, + negotiated_version = Version, %% Requested version + session = + Session0#session{session_id = Hello#client_hello.session_id}, + tls_handshake_history = Handshake, + start_or_recv_from = From, timer = Timer}, - {Record, State} = next_record(State1), - next_event(hello, Record, State); + next_event(hello, no_record, State); init(Type, Event, State) -> gen_handshake(?FUNCTION_NAME, Type, Event, State). @@ -610,36 +590,33 @@ connection(internal, #hello_request{}, connection_states = ConnectionStates} = State0) -> Hello = tls_handshake:client_hello(Host, Port, ConnectionStates, SslOpts, Cache, CacheCb, Renegotiation, Cert), - {State1, Actions} = send_handshake(Hello, State0), - {Record, State} = - next_record( - State1#state{session = Session0#session{session_id - = Hello#client_hello.session_id}}), - next_event(hello, Record, State, Actions); + {State, Actions} = send_handshake(Hello, State0), + next_event(hello, no_record, State#state{session = Session0#session{session_id + = Hello#client_hello.session_id}}, Actions); connection(internal, #client_hello{} = Hello, #state{role = server, allow_renegotiate = true, connection_states = CS, %%protocol_cb = Connection, protocol_specific = #{sender := Sender} - } = State0) -> + } = State) -> %% Mitigate Computational DoS attack %% http://www.educatedguesswork.org/2011/10/ssltls_and_computational_dos.html %% http://www.thc.org/thc-ssl-dos/ Rather than disabling client %% initiated renegotiation we will disallow many client initiated %% renegotiations immediately after each other. erlang:send_after(?WAIT_TO_ALLOW_RENEGOTIATION, self(), allow_renegotiate), - {Record, State} = next_record(State0#state{allow_renegotiate = false, - renegotiation = {true, peer}}), {ok, Write} = tls_sender:renegotiate(Sender), - next_event(hello, Record, State#state{connection_states = CS#{current_write => Write}}, + next_event(hello, no_record, State#state{connection_states = CS#{current_write => Write}, + allow_renegotiate = false, + renegotiation = {true, peer} + }, [{next_event, internal, Hello}]); connection(internal, #client_hello{}, #state{role = server, allow_renegotiate = false, protocol_cb = Connection} = State0) -> Alert = ?ALERT_REC(?WARNING, ?NO_RENEGOTIATION), send_alert_in_connection(Alert, State0), - State1 = Connection:reinit_handshake_data(State0), - {Record, State} = next_record(State1), - next_event(?FUNCTION_NAME, Record, State); + State = Connection:reinit_handshake_data(State0), + next_event(?FUNCTION_NAME, no_record, State); connection(Type, Event, State) -> ssl_connection:?FUNCTION_NAME(Type, Event, State, ?MODULE). @@ -688,6 +665,13 @@ initial_state(Role, Sender, Host, Port, Socket, {SSLOptions, SocketOptions, Trac _ -> ssl_session_cache end, + + InternalActiveN = case application:get_env(ssl, internal_active_n) of + {ok, N} when is_integer(N) andalso (not IsErlDist) -> + N; + _ -> + ?INTERNAL_ACTIVE_N + end, UserMonitor = erlang:monitor(process, User), @@ -714,7 +698,10 @@ initial_state(Role, Sender, Host, Port, Socket, {SSLOptions, SocketOptions, Trac protocol_cb = ?MODULE, tracker = Tracker, flight_buffer = [], - protocol_specific = #{sender => Sender} + protocol_specific = #{sender => Sender, + active_n => InternalActiveN, + active_n_toggle => true + } }. erl_dist_data(true) -> @@ -775,7 +762,8 @@ tls_handshake_events(Packets) -> %% raw data from socket, upack records handle_info({Protocol, _, Data}, StateName, - #state{data_tag = Protocol} = State0) -> + #state{data_tag = Protocol + } = State0) -> case next_tls_record(Data, StateName, State0) of {Record, State} -> next_event(StateName, Record, State); @@ -783,11 +771,16 @@ handle_info({Protocol, _, Data}, StateName, ssl_connection:handle_normal_shutdown(Alert, StateName, State0), ssl_connection:stop({shutdown, own_alert}, State0) end; +handle_info({tcp_passive, Socket}, StateName, #state{socket = Socket, + protocol_specific = PS + } = State) -> + next_event(StateName, no_record, State#state{protocol_specific = PS#{active_n_toggle => true}}); handle_info({CloseTag, Socket}, StateName, #state{socket = Socket, close_tag = CloseTag, socket_options = #socket_options{active = Active}, protocol_buffers = #protocol_buffers{tls_cipher_texts = CTs}, user_data_buffer = Buffer, + protocol_specific = PS, negotiated_version = Version} = State) -> %% Note that as of TLS 1.1, @@ -813,8 +806,9 @@ handle_info({CloseTag, Socket}, StateName, true -> %% Fixes non-delivery of final TLS record in {active, once}. %% Basically allows the application the opportunity to set {active, once} again - %% and then receive the final message. - next_event(StateName, no_record, State) + %% and then receive the final message. Set internal active_n to zero + %% to ensure socket close message is sent if there is not enough data to deliver. + next_event(StateName, no_record, State#state{protocol_specific = PS#{active_n_toggle => true}}) end; handle_info({'EXIT', Sender, Reason}, _, #state{protocol_specific = #{sender := Sender}} = State) -> diff --git a/lib/ssl/test/ssl_basic_SUITE.erl b/lib/ssl/test/ssl_basic_SUITE.erl index 6f668f0c00..9633800da5 100644 --- a/lib/ssl/test/ssl_basic_SUITE.erl +++ b/lib/ssl/test/ssl_basic_SUITE.erl @@ -1097,16 +1097,19 @@ tls_closed_in_active_once(Config) when is_list(Config) -> end. tls_closed_in_active_once_loop(Socket) -> - ssl:setopts(Socket, [{active, once}]), - receive - {ssl, Socket, _} -> - tls_closed_in_active_once_loop(Socket); - {ssl_closed, Socket} -> - ok - after 5000 -> - no_ssl_closed_received + case ssl:setopts(Socket, [{active, once}]) of + ok -> + receive + {ssl, Socket, _} -> + tls_closed_in_active_once_loop(Socket); + {ssl_closed, Socket} -> + ok + after 5000 -> + no_ssl_closed_received + end; + {error, closed} -> + ok end. - %%-------------------------------------------------------------------- connect_dist() -> [{doc,"Test a simple connect as is used by distribution"}]. @@ -5220,14 +5223,14 @@ get_invalid_inet_option(Socket) -> tls_shutdown_result(Socket, server) -> ssl:send(Socket, "Hej"), - ssl:shutdown(Socket, write), + ok = ssl:shutdown(Socket, write), {ok, "Hej hopp"} = ssl:recv(Socket, 8), ok; tls_shutdown_result(Socket, client) -> - {ok, "Hej"} = ssl:recv(Socket, 3), ssl:send(Socket, "Hej hopp"), - ssl:shutdown(Socket, write), + ok = ssl:shutdown(Socket, write), + {ok, "Hej"} = ssl:recv(Socket, 3), ok. tls_shutdown_write_result(Socket, server) -> diff --git a/lib/ssl/test/ssl_dist_bench_SUITE.erl b/lib/ssl/test/ssl_dist_bench_SUITE.erl index 3c7904cf24..7409b69639 100644 --- a/lib/ssl/test/ssl_dist_bench_SUITE.erl +++ b/lib/ssl/test/ssl_dist_bench_SUITE.erl @@ -32,6 +32,8 @@ -export( [setup/1, roundtrip/1, + throughput_0/1, + throughput_64/1, throughput_1024/1, throughput_4096/1, throughput_16384/1, @@ -55,7 +57,9 @@ groups() -> {setup, [{repeat, 1}], [setup]}, {roundtrip, [{repeat, 1}], [roundtrip]}, {throughput, [{repeat, 1}], - [throughput_1024, + [throughput_0, + throughput_64, + throughput_1024, throughput_4096, throughput_16384, throughput_65536, @@ -247,8 +251,9 @@ setup(A, B, Prefix, HA, HB) -> [] = ssl_apply(HB, erlang, nodes, []), {SetupTime, CycleTime} = ssl_apply(HA, fun () -> setup_runner(A, B, Rounds) end), - [] = ssl_apply(HA, erlang, nodes, []), - [] = ssl_apply(HB, erlang, nodes, []), + ok = ssl_apply(HB, fun () -> setup_wait_nodedown(A, 10000) end), + %% [] = ssl_apply(HA, erlang, nodes, []), + %% [] = ssl_apply(HB, erlang, nodes, []), SetupSpeed = round((Rounds*1000000*1000) / SetupTime), CycleSpeed = round((Rounds*1000000*1000) / CycleTime), _ = report(Prefix++" Setup", SetupSpeed, "setups/1000s"), @@ -275,6 +280,22 @@ setup_loop(A, B, T, N) -> setup_loop(A, B, Time + T, N - 1) end. +setup_wait_nodedown(A, Time) -> + ok = net_kernel:monitor_nodes(true), + case nodes() of + [] -> + ok; + [A] -> + receive + {nodedown,A} -> + ok; + Unexpected -> + {error,{unexpected,Unexpected}} + after Time -> + {error,timeout} + end + end. + %%---------------- %% Roundtrip speed @@ -334,6 +355,18 @@ roundtrip_client(Pid, Mon, StartTime, N) -> %%----------------- %% Throughput speed +throughput_0(Config) -> + run_nodepair_test( + fun (A, B, Prefix, HA, HB) -> + throughput(A, B, Prefix, HA, HB, 500000, 0) + end, Config). + +throughput_64(Config) -> + run_nodepair_test( + fun (A, B, Prefix, HA, HB) -> + throughput(A, B, Prefix, HA, HB, 500000, 64) + end, Config). + throughput_1024(Config) -> run_nodepair_test( fun (A, B, Prefix, HA, HB) -> @@ -373,45 +406,198 @@ throughput_1048576(Config) -> throughput(A, B, Prefix, HA, HB, Packets, Size) -> [] = ssl_apply(HA, erlang, nodes, []), [] = ssl_apply(HB, erlang, nodes, []), - Time = + #{time := Time, + dist_stats := DistStats, + client_msacc_stats := ClientMsaccStats, + client_prof := ClientProf, + server_msacc_stats := ServerMsaccStats, + server_prof := ServerProf} = ssl_apply(HA, fun () -> throughput_runner(A, B, Packets, Size) end), [B] = ssl_apply(HA, erlang, nodes, []), [A] = ssl_apply(HB, erlang, nodes, []), - Speed = round((Packets*Size*1000000) / (1024*Time)), + ClientMsaccStats =:= undefined orelse + msacc:print(ClientMsaccStats), + io:format("DistStats: ~p~n", [DistStats]), + Overhead = + 50 % Distribution protocol headers (empirical) (TLS+=54) + + byte_size(erlang:term_to_binary([0|<<>>])), % Benchmark overhead + Bytes = Packets * (Size + Overhead), + io:format("~w bytes, ~.4g s~n", [Bytes,Time/1000000]), + ClientMsaccStats =:= undefined orelse + io:format( + "Sender core usage ratio: ~.4g ns/byte~n", + [msacc:stats(system_runtime, ClientMsaccStats)*1000/Bytes]), + ServerMsaccStats =:= undefined orelse + begin + io:format( + "Receiver core usage ratio: ~.4g ns/byte~n", + [msacc:stats(system_runtime, ServerMsaccStats)*1000/Bytes]), + msacc:print(ServerMsaccStats) + end, + io:format("******* ClientProf:~n", []), prof_print(ClientProf), + io:format("******* ServerProf:~n", []), prof_print(ServerProf), + Speed = round((Bytes * 1000000) / (1024 * Time)), report(Prefix++" Throughput_"++integer_to_list(Size), Speed, "kB/s"). %% Runs on node A and spawns a server on node B throughput_runner(A, B, Rounds, Size) -> Payload = payload(Size), - ClientPid = self(), [A] = rpc:call(B, erlang, nodes, []), + ClientPid = self(), ServerPid = erlang:spawn( B, fun () -> throughput_server(ClientPid, Rounds) end), ServerMon = erlang:monitor(process, ServerPid), - microseconds( - throughput_client( - ServerPid, ServerMon, Payload, start_time(), Rounds)). + msacc:available() andalso + begin + msacc:stop(), + msacc:reset(), + msacc:start(), + ok + end, + prof_start(), + {Time,ServerMsaccStats,ServerProf} = + throughput_client(ServerPid, ServerMon, Payload, Rounds), + prof_stop(), + ClientMsaccStats = + case msacc:available() of + true -> + MStats = msacc:stats(), + msacc:stop(), + MStats; + false -> + undefined + end, + ClientProf = prof_end(), + [{_Node,Socket}] = dig_dist_node_sockets(), + DistStats = inet:getstat(Socket), + #{time => microseconds(Time), + dist_stats => DistStats, + client_msacc_stats => ClientMsaccStats, + client_prof => ClientProf, + server_msacc_stats => ServerMsaccStats, + server_prof => ServerProf}. + +dig_dist_node_sockets() -> + [case DistCtrl of + {_Node,Socket} = NodeSocket when is_port(Socket) -> + NodeSocket; + {Node,DistCtrlPid} when is_pid(DistCtrlPid) -> + [{links,DistCtrlLinks}] = process_info(DistCtrlPid, [links]), + case [S || S <- DistCtrlLinks, is_port(S)] of + [Socket] -> + {Node,Socket}; + [] -> + [{monitors,[{process,DistSenderPid}]}] = + process_info(DistCtrlPid, [monitors]), + [{links,DistSenderLinks}] = + process_info(DistSenderPid, [links]), + [Socket] = [S || S <- DistSenderLinks, is_port(S)], + {Node,Socket} + end + end || DistCtrl <- erlang:system_info(dist_ctrl)]. + -throughput_server(_Pid, 0) -> - ok; throughput_server(Pid, N) -> + msacc:available() andalso + begin + msacc:stop(), + msacc:reset(), + msacc:start(), + ok + end, + prof_start(), + throughput_server_loop(Pid, N). + +throughput_server_loop(_Pid, 0) -> + prof_stop(), + MsaccStats = + case msacc:available() of + true -> + msacc:stop(), + MStats = msacc:stats(), + msacc:reset(), + MStats; + false -> + undefined + end, + Prof = prof_end(), + exit({ok,MsaccStats,Prof}); +throughput_server_loop(Pid, N) -> receive - [N|_] -> - throughput_server(Pid, N-1) + {Pid, N, _} -> + throughput_server_loop(Pid, N-1) end. -throughput_client(_Pid, Mon, _Payload, StartTime, 0) -> +throughput_client(Pid, Mon, Payload, N) -> + throughput_client_loop(Pid, Mon, Payload, N, start_time()). + +throughput_client_loop(_Pid, Mon, _Payload, 0, StartTime) -> receive - {'DOWN', Mon, _, _, normal} -> - elapsed_time(StartTime); + {'DOWN', Mon, _, _, {ok,MsaccStats,Prof}} -> + {elapsed_time(StartTime),MsaccStats,Prof}; {'DOWN', Mon, _, _, Other} -> exit(Other) end; -throughput_client(Pid, Mon, Payload, StartTime, N) -> - Pid ! [N|Payload], - throughput_client(Pid, Mon, Payload, StartTime, N - 1). +throughput_client_loop(Pid, Mon, Payload, N, StartTime) -> + Pid ! {self(), N, Payload}, + throughput_client_loop(Pid, Mon, Payload, N - 1, StartTime). + + +-define(prof, none). % none | cprof | eprof + +-if(?prof =:= cprof). +prof_start() -> + cprof:stop(), + cprof:start(), + ok. +-elif(?prof =:= eprof). +prof_start() -> + {ok,_} = eprof:start(), + profiling = eprof:start_profiling(processes()), + ok. +-elif(?prof =:= none). +prof_start() -> + ok. +-endif. + +-if(?prof =:= cprof). +prof_stop() -> + cprof:pause(), + ok. +-elif(?prof =:= eprof). +prof_stop() -> + _ = eprof:stop_profiling(), + ok. +-elif(?prof =:= none). +prof_stop() -> + ok. +-endif. + +-if(?prof =:= cprof). +prof_end() -> + Prof = cprof:analyse(), + cprof:stop(), + Prof. +-elif(?prof =:= eprof). +prof_end() -> + eprof:dump_data(). +-elif(?prof =:= none). +prof_end() -> + []. +-endif. + +-if(?prof =:= cprof). +prof_print(Prof) -> + io:format("~p.~n", [Prof]). +-elif(?prof =:= eprof). +prof_print(Dump) -> + eprof:analyze(undefined, total, [], Dump). +-elif(?prof =:= none). +prof_print([]) -> + ok. +-endif. %%%------------------------------------------------------------------- %%% Test cases helpers diff --git a/lib/ssl/test/ssl_engine_SUITE.erl b/lib/ssl/test/ssl_engine_SUITE.erl index e6c82d3eb5..a39a62e550 100644 --- a/lib/ssl/test/ssl_engine_SUITE.erl +++ b/lib/ssl/test/ssl_engine_SUITE.erl @@ -46,10 +46,17 @@ init_per_suite(Config) -> ssl_test_lib:clean_start(), case crypto:get_test_engine() of {ok, EngineName} -> - try crypto:engine_load(<<"dynamic">>, - [{<<"SO_PATH">>, EngineName}, - <<"LOAD">>], - []) of + try + %% The test engine has it's own fake rsa sign/verify that + %% you don't want to use, so exclude it from methods to load: + Methods = + crypto:engine_get_all_methods() -- [engine_method_rsa], + crypto:engine_load(<<"dynamic">>, + [{<<"SO_PATH">>, EngineName}, + <<"LOAD">>], + [], + Methods) + of {ok, Engine} -> [{engine, Engine} |Config]; {error, Reason} -> diff --git a/lib/ssl/test/ssl_packet_SUITE.erl b/lib/ssl/test/ssl_packet_SUITE.erl index ebf8ddbfac..9af1ae0e3f 100644 --- a/lib/ssl/test/ssl_packet_SUITE.erl +++ b/lib/ssl/test/ssl_packet_SUITE.erl @@ -725,7 +725,7 @@ packet_switch(Config) when is_list(Config) -> {options, [{nodelay, true}, {packet, 2} | ClientOpts]}]), - ssl_test_lib:check_result(Client, ok), + ssl_test_lib:check_result(Client, ok, Server, ok), ssl_test_lib:close(Server), ssl_test_lib:close(Client). diff --git a/lib/ssl/test/ssl_test_lib.erl b/lib/ssl/test/ssl_test_lib.erl index 8a2f0824fb..a8d62d6c4e 100644 --- a/lib/ssl/test/ssl_test_lib.erl +++ b/lib/ssl/test/ssl_test_lib.erl @@ -26,6 +26,7 @@ %% Note: This directive should only be used in test suites. -compile(export_all). +-compile(nowarn_export_all). -record(sslsocket, { fd = nil, pid = nil}). -define(SLEEP, 1000). @@ -1706,10 +1707,10 @@ openssl_dsa_support() -> true; "LibreSSL" ++ _ -> false; - "OpenSSL 1.1" ++ Rest -> + "OpenSSL 1.1" ++ _Rest -> false; "OpenSSL 1.0.1" ++ Rest -> - hd(Rest) >= s; + hd(Rest) >= $s; _ -> true end. @@ -1746,8 +1747,6 @@ openssl_sane_client_cert() -> false; "LibreSSL 2.0" ++ _ -> false; - "LibreSSL 2.0" ++ _ -> - false; "OpenSSL 1.0.1s-freebsd" -> false; "OpenSSL 1.0.0" ++ _ -> diff --git a/lib/stdlib/doc/src/calendar.xml b/lib/stdlib/doc/src/calendar.xml index 6b4fa7f98a..5aee635c38 100644 --- a/lib/stdlib/doc/src/calendar.xml +++ b/lib/stdlib/doc/src/calendar.xml @@ -403,7 +403,11 @@ default is <c>second</c>. If some other unit is given (<c>millisecond</c>, <c>microsecond</c>, or <c>nanosecond</c>), the formatted string includes a - fraction of a second.</p> + fraction of a second. The number of fractional second + digits is three, six, or nine depending on what time unit + is chosen. Notice that trailing zeros are not removed from + the fraction. + </p> </item> </taglist> <pre> diff --git a/lib/stdlib/src/calendar.erl b/lib/stdlib/src/calendar.erl index 9a600c1972..bb5d450cd6 100644 --- a/lib/stdlib/src/calendar.erl +++ b/lib/stdlib/src/calendar.erl @@ -693,14 +693,11 @@ local_offset(SystemTime, Unit) -> UniversalSecs = datetime_to_gregorian_seconds(UniversalTime), LocalSecs - UniversalSecs. +fraction_str(1, _Time) -> + ""; fraction_str(Factor, Time) -> - case Time rem Factor of - 0 -> - ""; - Fraction -> - FS = io_lib:fwrite(".~*..0B", [log10(Factor), abs(Fraction)]), - string:trim(FS, trailing, "0") - end. + Fraction = Time rem Factor, + io_lib:fwrite(".~*..0B", [log10(Factor), abs(Fraction)]). fraction(second, _) -> 0; diff --git a/lib/stdlib/src/erl_lint.erl b/lib/stdlib/src/erl_lint.erl index e9ac2fcdff..e0cd68617b 100644 --- a/lib/stdlib/src/erl_lint.erl +++ b/lib/stdlib/src/erl_lint.erl @@ -2262,8 +2262,7 @@ expr({'fun',Line,Body}, Vt, St) -> {[],St}; {function,M,F,A} -> %% New in R15. - {Bvt, St1} = expr_list([M,F,A], Vt, St), - {vtupdate(Bvt, Vt),St1} + expr_list([M,F,A], Vt, St) end; expr({named_fun,_,'_',Cs}, Vt, St) -> fun_clauses(Cs, Vt, St); diff --git a/lib/stdlib/test/calendar_SUITE.erl b/lib/stdlib/test/calendar_SUITE.erl index 55118e251c..df62c0921d 100644 --- a/lib/stdlib/test/calendar_SUITE.erl +++ b/lib/stdlib/test/calendar_SUITE.erl @@ -183,14 +183,15 @@ rfc3339(Config) when is_list(Config) -> D = [{time_designator, $\s}], Z = [{offset, "Z"}], - "1985-04-12T23:20:50.52Z" = test_parse("1985-04-12T23:20:50.52Z", Ms), - "1985-04-12T23:20:50.52Z" = test_parse("1985-04-12t23:20:50.52z", Ms), - "1985-04-12T21:20:50.52Z" = + "1985-04-12T23:20:50.520Z" = test_parse("1985-04-12T23:20:50.52Z", Ms), + "1985-04-12T23:20:50.520Z" = test_parse("1985-04-12t23:20:50.52z", Ms), + "1985-04-12T21:20:50.520Z" = test_parse("1985-04-12T23:20:50.52+02:00", Ms), "1985-04-12T23:20:50Z" = test_parse("1985-04-12T23:20:50.52Z", S), - "1985-04-12T23:20:50.52Z" = test_parse("1985-04-12T23:20:50.52Z", Ms), - "1985-04-12T23:20:50.52Z" = test_parse("1985-04-12t23:20:50.52z", Mys), - "1985-04-12 21:20:50.52Z" = + "1985-04-12T23:20:50.520Z" = test_parse("1985-04-12T23:20:50.52Z", Ms), + "1985-04-12T23:20:50.520000Z" = + test_parse("1985-04-12t23:20:50.52z", Mys), + "1985-04-12 21:20:50.520000000Z" = test_parse("1985-04-12 23:20:50.52+02:00", Ns++D), "1985-04-12T23:20:50Z" = test_parse("1985-04-12T23:20:50.52Z"), "1996-12-20T00:39:57Z" = test_parse("1996-12-19T16:39:57-08:00"), @@ -221,17 +222,20 @@ rfc3339(Config) when is_list(Config) -> "1970-01-02T00:00:00Z" = test_parse("1970-01-01T23:59:60Z"), "1970-01-02T00:00:00Z" = test_parse("1970-01-01T23:59:60.5Z"), "1970-01-02T00:00:00Z" = test_parse("1970-01-01T23:59:60.55Z"), - "1970-01-02T00:00:00.55Z" = test_parse("1970-01-01T23:59:60.55Z", Ms), - "1970-01-02T00:00:00.55Z" = test_parse("1970-01-01T23:59:60.55Z", Mys), - "1970-01-02T00:00:00.55Z" = test_parse("1970-01-01T23:59:60.55Z", Ns), + "1970-01-02T00:00:00.550Z" = test_parse("1970-01-01T23:59:60.55Z", Ms), + "1970-01-02T00:00:00.550000Z" = + test_parse("1970-01-01T23:59:60.55Z", Mys), + "1970-01-02T00:00:00.550000000Z" = + test_parse("1970-01-01T23:59:60.55Z", Ns), "1970-01-02T00:00:00.999999Z" = test_parse("1970-01-01T23:59:60.999999Z", Mys), - "1970-01-02T00:00:01Z" = + "1970-01-02T00:00:01.000Z" = test_parse("1970-01-01T23:59:60.999999Z", Ms), "1970-01-01T00:00:00Z" = test_parse("1970-01-01T00:00:00+00:00"), "1970-01-01T00:00:00Z" = test_parse("1970-01-01T00:00:00-00:00"), "1969-12-31T00:01:00Z" = test_parse("1970-01-01T00:00:00+23:59"), - "1918-11-11T09:00:00Z" = test_parse("1918-11-11T11:00:00+02:00", Mys), + "1918-11-11T09:00:00.000000Z" = + test_parse("1918-11-11T11:00:00+02:00", Mys), "1970-01-01T00:00:00.000001Z" = test_parse("1970-01-01T00:00:00.000001Z", Mys), @@ -242,26 +246,26 @@ rfc3339(Config) when is_list(Config) -> test_time(erlang:system_time(millisecond), Ms), test_time(erlang:system_time(microsecond), Mys++[{offset, "-02:20"}]), - T = erlang:system_time(second), - TS = do_format(T, []), - TS = do_format(T * 1000, Ms), - TS = do_format(T * 1000 * 1000, Mys), - TS = do_format(T * 1000 * 1000 * 1000, Ns), - 946720800 = TO = do_parse("2000-01-01 10:00:00Z", []), Str = "2000-01-01T10:02:00+00:02", Str = do_format(TO, [{offset, 120}]), - Str = do_format(TO * 1000, [{offset, 120 * 1000}]++Ms), - Str = do_format(TO * 1000 * 1000, [{offset, 120 * 1000 * 1000}]++Mys), - Str = do_format(TO * 1000 * 1000 * 1000, - [{offset, 120 * 1000 * 1000 * 1000}]++Ns), + "2000-01-01T10:02:00.000+00:02" = + do_format(TO * 1000, [{offset, 120 * 1000}]++Ms), + "2000-01-01T10:02:00.000000+00:02" = + do_format(TO * 1000 * 1000, [{offset, 120 * 1000 * 1000}]++Mys), + "2000-01-01T10:02:00.000000000+00:02" = + do_format(TO * 1000 * 1000 * 1000, + [{offset, 120 * 1000 * 1000 * 1000}]++Ns), NStr = "2000-01-01T09:58:00-00:02", NStr = do_format(TO, [{offset, -120}]), - NStr = do_format(TO * 1000, [{offset, -120 * 1000}]++Ms), - NStr = do_format(TO * 1000 * 1000, [{offset, -120 * 1000 * 1000}]++Mys), - NStr = do_format(TO * 1000 * 1000 * 1000, - [{offset, -120 * 1000 * 1000 * 1000}]++Ns), + "2000-01-01T09:58:00.000-00:02" = + do_format(TO * 1000, [{offset, -120 * 1000}]++Ms), + "2000-01-01T09:58:00.000000-00:02" = + do_format(TO * 1000 * 1000, [{offset, -120 * 1000 * 1000}]++Mys), + "2000-01-01T09:58:00.000000000-00:02" = + do_format(TO * 1000 * 1000 * 1000, + [{offset, -120 * 1000 * 1000 * 1000}]++Ns), 543210000 = do_parse("1970-01-01T00:00:00.54321Z", Ns), 54321000 = do_parse("1970-01-01T00:00:00.054321Z", Ns), @@ -278,18 +282,18 @@ rfc3339(Config) when is_list(Config) -> -1613833200000000 = do_parse("1918-11-11T11:00:00+02:00", Mys), -1613833200000000 = do_parse("1918-11-11T09:00:00Z", Mys), - "1970-01-01T00:00:00Z" = do_format_z(0, Mys), + "1970-01-01T00:00:00.000000Z" = do_format_z(0, Mys), "1970-01-01T00:00:01Z" = do_format_z(1, S), "1970-01-01T00:00:00.001Z" = do_format_z(1, Ms), "1970-01-01T00:00:00.000001Z" = do_format_z(1, Mys), "1970-01-01T00:00:00.000000001Z" = do_format_z(1, Ns), - "1970-01-01T00:00:01Z" = do_format_z(1000000, Mys), - "1970-01-01T00:00:00.54321Z" = do_format_z(543210, Mys), + "1970-01-01T00:00:01.000000Z" = do_format_z(1000000, Mys), + "1970-01-01T00:00:00.543210Z" = do_format_z(543210, Mys), "1970-01-01T00:00:00.543Z" = do_format_z(543, Ms), - "1970-01-01T00:00:00.54321Z" = do_format_z(543210000, Ns), - "1970-01-01T00:00:06.54321Z" = do_format_z(6543210, Mys), - "1979-06-21T12:12:12Z" = do_format_z(298815132000000, Mys), - "1918-11-11T13:00:00Z" = do_format_z(-1613818800000000, Mys), + "1970-01-01T00:00:00.543210000Z" = do_format_z(543210000, Ns), + "1970-01-01T00:00:06.543210Z" = do_format_z(6543210, Mys), + "1979-06-21T12:12:12.000000Z" = do_format_z(298815132000000, Mys), + "1918-11-11T13:00:00.000000Z" = do_format_z(-1613818800000000, Mys), ok. %% diff --git a/lib/stdlib/test/erl_lint_SUITE.erl b/lib/stdlib/test/erl_lint_SUITE.erl index f9ab83a120..d18c7c255c 100644 --- a/lib/stdlib/test/erl_lint_SUITE.erl +++ b/lib/stdlib/test/erl_lint_SUITE.erl @@ -67,7 +67,8 @@ record_errors/1, otp_11879_cont/1, non_latin1_module/1, otp_14323/1, stacktrace_syntax/1, - otp_14285/1, otp_14378/1]). + otp_14285/1, otp_14378/1, + external_funs/1]). suite() -> [{ct_hooks,[ts_install_cth]}, @@ -88,7 +89,7 @@ all() -> maps, maps_type, maps_parallel_match, otp_11851, otp_11879, otp_13230, record_errors, otp_11879_cont, non_latin1_module, otp_14323, - stacktrace_syntax, otp_14285, otp_14378]. + stacktrace_syntax, otp_14285, otp_14378, external_funs]. groups() -> [{unused_vars_warn, [], @@ -4134,6 +4135,21 @@ otp_14285(Config) -> run(Config, Ts), ok. +external_funs(Config) when is_list(Config) -> + Ts = [{external_funs_1, + %% ERL-762: Unused variable warning not being emitted. + <<"f() -> + BugVar = process_info(self()), + if true -> fun m:f/1 end. + f(M, F) -> + BugVar = process_info(self()), + if true -> fun M:F/1 end.">>, + [], + {warnings,[{2,erl_lint,{unused_var,'BugVar'}}, + {5,erl_lint,{unused_var,'BugVar'}}]}}], + run(Config, Ts), + ok. + format_error(E) -> lists:flatten(erl_lint:format_error(E)). diff --git a/lib/stdlib/test/unicode_util_SUITE.erl b/lib/stdlib/test/unicode_util_SUITE.erl index 962b307b07..044b4e5834 100644 --- a/lib/stdlib/test/unicode_util_SUITE.erl +++ b/lib/stdlib/test/unicode_util_SUITE.erl @@ -126,17 +126,30 @@ verify_gc(Line0, N, Acc) -> %io:format("Line: ~s~n",[Line]), [Data|_Comments] = string:tokens(Line, "#"), - %io:format("Data: ~w~n",[string:tokens(Data, " \t")]), + %% io:format("Data: ~w~n",[string:tokens(Data, " \t")]), {Str,Res} = gc_test_data(string:tokens(Data, " \t"), [], [[]]), - try - Res = fetch(Str, fun unicode_util:gc/1), - Acc - catch _Cl:{badmatch, Other} -> + %% io:format("InputStr: ~w ~w~n",[Str,unicode:characters_to_binary(Str)]), + case verify_gc(Str, Res, N, Line) andalso + verify_gc(unicode:characters_to_binary(Str), Res, N, Line0) of + true -> Acc; + false -> Acc+1 + end. + +verify_gc({error,_,[CP|_]}=Err, _Res, N, Line) -> + IsSurrogate = 16#D800 =< CP andalso CP =< 16#DFFF, + %% Surrogat is not valid in utf8 encoding only utf16 + IsSurrogate orelse + io:format("~w: ~ts~n Error in unicode:characters_to_binary ~w~n", [N, Line, Err]), + IsSurrogate; +verify_gc(Str, Res, N, Line) -> + try fetch(Str, fun unicode_util:gc/1) of + Res -> true; + Other -> io:format("Failed: ~p~nInput: ~ts~n\t=> ~w |~ts|~n",[N, Line, Str, Str]), io:format("Expected: ~p~n", [Res]), io:format("Got: ~w~n", [Other]), - Acc+1; - Cl:R:Stacktrace -> + false + catch Cl:R:Stacktrace -> io:format("~p: ~ts => |~tp|~n",[N, Line, Str]), io:format("Expected: ~p~n", [Res]), erlang:raise(Cl,R,Stacktrace) diff --git a/lib/stdlib/uc_spec/gen_unicode_mod.escript b/lib/stdlib/uc_spec/gen_unicode_mod.escript index fe5a860d45..535f01a1c5 100755 --- a/lib/stdlib/uc_spec/gen_unicode_mod.escript +++ b/lib/stdlib/uc_spec/gen_unicode_mod.escript @@ -646,7 +646,7 @@ gen_gc(Fd, GBP) -> io:put_chars(Fd, "is_emodifier(_) -> false.\n\n"), io:put_chars(Fd, "gc_zwj(R0, Acc) ->\n case cp(R0) of\n"), - GenZWJGlue = fun(Range) -> io:format(Fd, "~8c~s gc_extend(R1, R0, [CP|Acc]);\n", + GenZWJGlue = fun(Range) -> io:format(Fd, "~8c~s gc_extend(cp(R1), R0, [CP|Acc]);\n", [$\s,gen_case_clause(Range)]) end, [GenZWJGlue(CP) || CP <- merge_ranges(maps:get(glue_after_zwj,GBP))], GenZWJEBG = fun(Range) -> io:format(Fd, "~8c~s gc_e_cont(R1, [CP|Acc]);\n", diff --git a/lib/tools/src/eprof.erl b/lib/tools/src/eprof.erl index 535ddbcd04..86e3d3a8b8 100644 --- a/lib/tools/src/eprof.erl +++ b/lib/tools/src/eprof.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 1996-2017. All Rights Reserved. +%% Copyright Ericsson AB 1996-2018. All Rights Reserved. %% %% Licensed under the Apache License, Version 2.0 (the "License"); %% you may not use this file except in compliance with the License. @@ -26,11 +26,11 @@ -export([start/0, stop/0, - dump/0, + dump/0, dump_data/0, start_profiling/1, start_profiling/2, start_profiling/3, profile/1, profile/2, profile/3, profile/4, profile/5, stop_profiling/0, - analyze/0, analyze/1, analyze/2, + analyze/0, analyze/1, analyze/2, analyze/4, log/1]). %% Internal exports @@ -117,6 +117,9 @@ profile(Rootset, M, F, A, Pattern, Options) -> dump() -> gen_server:call(?MODULE, dump, infinity). +dump_data() -> + gen_server:call(?MODULE, dump_data, infinity). + log(File) -> gen_server:call(?MODULE, {logfile, File}, infinity). @@ -151,22 +154,18 @@ init([]) -> %% analyze -handle_call({analyze, _, _}, _, #state{ bpd = #bpd{ p = {0,nil}, us = 0, n = 0} = Bpd } = S) when is_record(Bpd, bpd) -> +handle_call( + {analyze, _, _}, _, + #state{ bpd = #bpd{ p = {0,nil}, us = 0, n = 0 } } = S) -> {reply, nothing_to_analyze, S}; -handle_call({analyze, procs, Opts}, _, #state{ bpd = #bpd{ p = Ps, us = Tus} = Bpd, fd = Fd} = S) when is_record(Bpd, bpd) -> - lists:foreach(fun - ({Pid, Mfas}) -> - {Pn, Pus} = sum_bp_total_n_us(Mfas), - format(Fd, "~n****** Process ~w -- ~s % of profiled time *** ~n", [Pid, s("~.2f", [100.0*divide(Pus,Tus)])]), - print_bp_mfa(Mfas, {Pn,Pus}, Fd, Opts), - ok - end, gb_trees:to_list(Ps)), - {reply, ok, S}; +handle_call({analyze, procs, Opts}, _, #state{ bpd = Bpd, fd = Fd } = S) + when is_record(Bpd, bpd) -> + {reply, analyze(Fd, procs, Opts, Bpd), S}; -handle_call({analyze, total, Opts}, _, #state{ bpd = #bpd{ mfa = Mfas, n = Tn, us = Tus} = Bpd, fd = Fd} = S) when is_record(Bpd, bpd) -> - print_bp_mfa(Mfas, {Tn, Tus}, Fd, Opts), - {reply, ok, S}; +handle_call({analyze, total, Opts}, _, #state{ bpd = Bpd, fd = Fd } = S) + when is_record(Bpd, bpd) -> + {reply, analyze(Fd, total, Opts, Bpd), S}; handle_call({analyze, Type, _Opts}, _, S) -> {reply, {error, {undefined, Type}}, S}; @@ -260,6 +259,10 @@ handle_call({logfile, File}, _From, #state{ fd = OldFd } = S) -> handle_call(dump, _From, #state{ bpd = Bpd } = S) when is_record(Bpd, bpd) -> {reply, gb_trees:to_list(Bpd#bpd.p), S}; +handle_call(dump_data, _, #state{ bpd = #bpd{} = Bpd } = S) + when is_record(Bpd, bpd) -> + {reply, Bpd, S}; + handle_call(stop, _FromTag, S) -> {stop, normal, stopped, S}. @@ -438,6 +441,23 @@ collect_bpdfp(Mfa, Tree, Data) -> {PTno + Ni, PTuso + Time, Ti1} end, {0,0, Tree}, Data). + + +analyze(Fd, procs, Opts, #bpd{ p = Ps, us = Tus }) -> + lists:foreach( + fun + ({Pid, Mfas}) -> + {Pn, Pus} = sum_bp_total_n_us(Mfas), + format( + Fd, + "~n****** Process ~w -- ~s % of profiled time *** ~n", + [Pid, s("~.2f", [100.0*divide(Pus, Tus)])]), + print_bp_mfa(Mfas, {Pn,Pus}, Fd, Opts), + ok + end, gb_trees:to_list(Ps)); +analyze(Fd, total, Opts, #bpd{ mfa = Mfas, n = Tn, us = Tus } ) -> + print_bp_mfa(Mfas, {Tn, Tus}, Fd, Opts). + %% manipulators sort_mfa(Bpfs, mfa) when is_list(Bpfs) -> lists:sort(fun diff --git a/lib/wx/api_gen/wx_gen_cpp.erl b/lib/wx/api_gen/wx_gen_cpp.erl index 70a3530526..f13d5873a0 100644 --- a/lib/wx/api_gen/wx_gen_cpp.erl +++ b/lib/wx/api_gen/wx_gen_cpp.erl @@ -995,8 +995,13 @@ build_ret_types(Type,Ps) -> end, lists:foldl(Calc, Free, Ps). -build_ret(Name,_,#type{base={class,Class},single=true}) -> - w(" rt.addRef(getRef((void *)~s,memenv), \"~s\");~n",[Name,Class]); +build_ret(Name,_D,#type{base={class,Class},single=true}=_T) -> + case Class of + "wxGraphicsContext" -> + w(" rt.addRef(getRef((void *)~s,memenv,8), \"~s\");~n",[Name,Class]); + _ -> + w(" rt.addRef(getRef((void *)~s,memenv), \"~s\");~n",[Name,Class]) + end; build_ret(Name,_,#type{name="wxTreeItemId",single=true}) -> w(" rt.add((wxUIntPtr *) ~s.m_pItem);~n",[Name]); build_ret(Name,_,#type{name="wxTreeItemIdValue",single=true}) -> diff --git a/lib/wx/c_src/gen/wxe_funcs.cpp b/lib/wx/c_src/gen/wxe_funcs.cpp index a7bac4cf9d..74961b2e5e 100644 --- a/lib/wx/c_src/gen/wxe_funcs.cpp +++ b/lib/wx/c_src/gen/wxe_funcs.cpp @@ -6147,18 +6147,18 @@ case wxGraphicsObject_IsNull: { // wxGraphicsObject::IsNull case wxGraphicsContext_Create_1_1: { // wxGraphicsContext::Create wxWindowDC * dc = (wxWindowDC *) getPtr(bp,memenv); bp += 4; wxGraphicsContext * Result = (wxGraphicsContext*)wxGraphicsContext::Create(*dc); - rt.addRef(getRef((void *)Result,memenv), "wxGraphicsContext"); + rt.addRef(getRef((void *)Result,memenv,8), "wxGraphicsContext"); break; } case wxGraphicsContext_Create_1_0: { // wxGraphicsContext::Create wxWindow *window = (wxWindow *) getPtr(bp,memenv); bp += 4; wxGraphicsContext * Result = (wxGraphicsContext*)wxGraphicsContext::Create(window); - rt.addRef(getRef((void *)Result,memenv), "wxGraphicsContext"); + rt.addRef(getRef((void *)Result,memenv,8), "wxGraphicsContext"); break; } case wxGraphicsContext_Create_0: { // wxGraphicsContext::Create wxGraphicsContext * Result = (wxGraphicsContext*)wxGraphicsContext::Create(); - rt.addRef(getRef((void *)Result,memenv), "wxGraphicsContext"); + rt.addRef(getRef((void *)Result,memenv,8), "wxGraphicsContext"); break; } case wxGraphicsContext_CreatePen: { // wxGraphicsContext::CreatePen @@ -6999,7 +6999,7 @@ case wxGraphicsRenderer_CreateContext_1_1: { // wxGraphicsRenderer::CreateContex wxWindowDC * dc = (wxWindowDC *) getPtr(bp,memenv); bp += 4; if(!This) throw wxe_badarg(0); wxGraphicsContext * Result = (wxGraphicsContext*)This->CreateContext(*dc); - rt.addRef(getRef((void *)Result,memenv), "wxGraphicsContext"); + rt.addRef(getRef((void *)Result,memenv,8), "wxGraphicsContext"); break; } case wxGraphicsRenderer_CreateContext_1_0: { // wxGraphicsRenderer::CreateContext @@ -7007,7 +7007,7 @@ case wxGraphicsRenderer_CreateContext_1_0: { // wxGraphicsRenderer::CreateContex wxWindow *window = (wxWindow *) getPtr(bp,memenv); bp += 4; if(!This) throw wxe_badarg(0); wxGraphicsContext * Result = (wxGraphicsContext*)This->CreateContext(window); - rt.addRef(getRef((void *)Result,memenv), "wxGraphicsContext"); + rt.addRef(getRef((void *)Result,memenv,8), "wxGraphicsContext"); break; } diff --git a/lib/wx/c_src/wxe_impl.cpp b/lib/wx/c_src/wxe_impl.cpp index 1510866f09..f856099ffa 100644 --- a/lib/wx/c_src/wxe_impl.cpp +++ b/lib/wx/c_src/wxe_impl.cpp @@ -591,7 +591,7 @@ int WxeApp::newPtr(void * ptr, int type, wxeMemEnv *memenv) { return ref; } -int WxeApp::getRef(void * ptr, wxeMemEnv *memenv) { +int WxeApp::getRef(void * ptr, wxeMemEnv *memenv, int type) { if(!ptr) return 0; // NULL and zero is the same ptrMap::iterator it = ptr2ref.find(ptr); if(it != ptr2ref.end()) { @@ -618,7 +618,7 @@ int WxeApp::getRef(void * ptr, wxeMemEnv *memenv) { } memenv->ref2ptr[ref] = ptr; - ptr2ref[ptr] = new wxeRefData(ref, 0, false, memenv); + ptr2ref[ptr] = new wxeRefData(ref, type, false, memenv); return ref; } diff --git a/lib/wx/c_src/wxe_impl.h b/lib/wx/c_src/wxe_impl.h index 140a2bd36a..69cc81c429 100644 --- a/lib/wx/c_src/wxe_impl.h +++ b/lib/wx/c_src/wxe_impl.h @@ -84,7 +84,7 @@ public: wxeMemEnv * getMemEnv(ErlDrvTermData port); int newPtr(void * ptr, int type, wxeMemEnv *memenv); - int getRef(void * ptr, wxeMemEnv *memenv); + int getRef(void * ptr, wxeMemEnv *memenv, int type = 0); void * getPtr(char * bp, wxeMemEnv *memenv); void clearPtr(void *ptr); wxeRefData * getRefData(void *ptr); |